From ec76844da85b0bae2c5e986b7e7b3682ae69b575 Mon Sep 17 00:00:00 2001 From: yml2213 Date: Fri, 18 Sep 2026 15:04:38 +0800 Subject: [PATCH] =?UTF-8?q?feat(log):=20=E5=85=A8=E9=9D=A2=E9=87=8D?= =?UTF-8?q?=E6=9E=84=E6=97=A5=E5=BF=97=E7=B3=BB=E7=BB=9F=EF=BC=8C=E6=94=AF?= =?UTF-8?q?=E6=8C=81=E6=97=A5=E5=BF=97=E7=BA=A7=E5=88=AB=E3=80=81=E5=8E=BB?= =?UTF-8?q?=E9=99=A4ANSI=E4=B9=B1=E7=A0=81=E5=B9=B6=E6=8A=91=E5=88=B6?= =?UTF-8?q?=E9=AB=98=E9=A2=91=E8=BD=AE=E8=AF=A2?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- backend/cmd/server/main.go | 11 +- backend/internal/config/config.go | 3 + backend/internal/handler/open.go | 4 +- backend/internal/handler/open_v1.go | 18 +-- backend/internal/middleware/open_auth.go | 2 +- .../internal/middleware/source_open_auth.go | 2 +- backend/internal/pkg/applog/applog.go | 109 +++++++++++++++++- backend/internal/pkg/applog/applog_test.go | 101 ++++++++++------ backend/internal/pkg/openlog/openlog.go | 61 ++++++---- backend/internal/pkg/openlog/openlog_test.go | 2 +- backend/internal/router/router.go | 81 ++++++++++++- backend/internal/router/router_test.go | 99 ++++++++++++++++ backend/internal/service/callback.go | 12 +- .../internal/service/fulfillment_timeout.go | 6 +- backend/internal/service/recharge.go | 4 +- 15 files changed, 415 insertions(+), 100 deletions(-) diff --git a/backend/cmd/server/main.go b/backend/cmd/server/main.go index 31b0348..0f46862 100644 --- a/backend/cmd/server/main.go +++ b/backend/cmd/server/main.go @@ -39,6 +39,7 @@ func main() { // 日志：控制台 + 文件 applog.SetRetainDays(cfg.LogRetainDays) + applog.SetLevel(cfg.LogLevel) logFile, err := applog.Setup(cfg.LogFile) if err != nil { log.Fatalf("setup log: %v", err) @@ -132,14 +133,14 @@ func main() { r := router.Setup(h) addr := ":" + cfg.Port - log.Printf("游戏皮肤供货平台 API 启动: http://localhost%s", addr) - log.Printf("数据库: PostgreSQL") - log.Printf("开放接口鉴权: X-App-Key + X-Timestamp + X-Nonce + X-Sign (HMAC-SHA256)") + applog.Infof("游戏皮肤供货平台 API 启动: http://localhost%s (日志级别: %s)", addr, applog.GetLevel()) + applog.Infof("数据库: PostgreSQL") + applog.Infof("开放接口鉴权: X-App-Key + X-Timestamp + X-Nonce + X-Sign (HMAC-SHA256)") if cfg.OpenAPIDebug { - log.Printf("开放接口调试日志: 开启 (OPEN_API_DEBUG=0 可关闭)") + applog.Infof("开放接口调试日志: 开启 (OPEN_API_DEBUG=0 可关闭)") } if cfg.LogFile != "" { - log.Printf("日志文件: %s （同时输出控制台）", cfg.LogFile) + applog.Infof("日志文件: %s （同时输出控制台）", cfg.LogFile) } if err := r.Run(addr); err != nil { log.Fatalf("server: %v", err) diff --git a/backend/internal/config/config.go b/backend/internal/config/config.go index 60763bf..ffa027e 100644 --- a/backend/internal/config/config.go +++ b/backend/internal/config/config.go @@ -24,6 +24,8 @@ type Config struct { OpenSignSkew int64 // OpenAPIDebug 开放接口详细调试日志 OpenAPIDebug bool + // LogLevel 日志级别: debug / info / warn / error（默认 info） + LogLevel string // LogFile 日志文件路径；非空时同时写控制台与文件（按天分割） LogFile string // LogRetainDays 日志文件保留天数（按天分割后自动清理旧文件） @@ -79,6 +81,7 @@ func Load() *Config { OpenAPISecret: getEnv("OPEN_API_SECRET", "sk_source_dev_secret_change_me"), OpenSignSkew: int64(getEnvInt("OPEN_SIGN_SKEW", 300)), OpenAPIDebug: debugOpen, + LogLevel: getEnv("LOG_LEVEL", "info"), LogFile: getEnv("LOG_FILE", "logs/app.log"), LogRetainDays: getEnvInt("LOG_RETAIN_DAYS", 30), DeliveryBaseURL: getEnv("DELIVERY_BASE_URL", ""), diff --git a/backend/internal/handler/open.go b/backend/internal/handler/open.go index 890dbdf..82c671c 100644 --- a/backend/internal/handler/open.go +++ b/backend/internal/handler/open.go @@ -28,7 +28,7 @@ func (h *OpenHandler) QueryOrder(c *gin.Context) { if orderNo == "" { orderNo = c.Query("order_no") } - openlog.Info(c, "query_order start order_no=%s", orderNo) + openlog.Debug(c, "query_order start order_no=%s", orderNo) data, err := h.fulfillmentSvc.QueryOpenOrder(orderNo) if err != nil { @@ -45,7 +45,7 @@ func (h *OpenHandler) QueryOrder(c *gin.Context) { if data.Product != nil { sku, name, game = data.Product.SKU, data.Product.Name, data.Product.Game } - openlog.Info(c, "query_order ok order_no=%s status=%s can_ship=%v reason=%q sku=%s name=%s game=%s buyer=%s amount=%d provider_no=%s shipped_at=%v fail_reason=%q game_channel=%s game_uid=%s role_name=%s pay_score=%d", + openlog.Debug(c, "query_order ok order_no=%s status=%s can_ship=%v reason=%q sku=%s name=%s game=%s buyer=%s amount=%d provider_no=%s shipped_at=%v fail_reason=%q game_channel=%s game_uid=%s role_name=%s pay_score=%d", data.OrderNo, data.Status, data.CanShip, data.CannotShipReason, sku, name, game, data.BuyerName, data.Amount, data.ProviderOrderNo, data.ShippedAt, data.ShipFailReason, data.GameChannel, data.GameUID, data.RoleName, data.PayScore, diff --git a/backend/internal/handler/open_v1.go b/backend/internal/handler/open_v1.go index 0c56cdc..02c1887 100644 --- a/backend/internal/handler/open_v1.go +++ b/backend/internal/handler/open_v1.go @@ -30,14 +30,14 @@ func (h *OpenV1Handler) ListProducts(c *gin.Context) { openlog.SetAction(c, openlog.ActionList) page, _ := strconv.Atoi(c.DefaultQuery("page", "1")) size, _ := strconv.Atoi(c.DefaultQuery("size", "20")) - openlog.Info(c, "list_products start page=%d size=%d", page, size) + openlog.Debug(c, "list_products start page=%d size=%d", page, size) list, total, err := h.merchantSvc.ListMerchantProductsForClient(middleware.GetMerchantID(c), page, size) if err != nil { openlog.Warn(c, "list_products fail err=%v", err) response.ServerError(c, err.Error()) return } - openlog.Info(c, "list_products ok total=%d returned=%d", total, len(list)) + openlog.Debug(c, "list_products ok total=%d returned=%d", total, len(list)) response.Page(c, list, total, page, size) } @@ -110,7 +110,7 @@ func (h *OpenV1Handler) CreateOrder(c *gin.Context) { func (h *OpenV1Handler) QueryOrder(c *gin.Context) { openlog.SetAction(c, openlog.ActionQuery) orderNo := c.Param("order_no") - openlog.Info(c, "query_order start order_no=%s", orderNo) + openlog.Debug(c, "query_order start order_no=%s", orderNo) order, err := h.fulfillmentSvc.GetOrder(middleware.GetMerchantID(c), orderNo) if err != nil { openlog.Warn(c, "query_order fail order_no=%s err=%v", orderNo, err) @@ -121,7 +121,7 @@ func (h *OpenV1Handler) QueryOrder(c *gin.Context) { response.ServerError(c, err.Error()) return } - openlog.Info(c, "query_order ok order_no=%s status=%s", + openlog.Debug(c, "query_order ok order_no=%s status=%s", order.OrderNo, order.OrderStatus) response.OK(c, buildOpenOrderResponse(order)) } @@ -153,14 +153,14 @@ func (h *OpenV1Handler) CancelOrder(c *gin.Context) { func (h *OpenV1Handler) GetWallet(c *gin.Context) { openlog.SetAction(c, openlog.ActionWallet) - openlog.Info(c, "get_wallet start") + openlog.Debug(c, "get_wallet start") wallet, err := h.fulfillmentSvc.GetWallet(middleware.GetMerchantID(c)) if err != nil { openlog.Warn(c, "get_wallet fail err=%v", err) response.ServerError(c, err.Error()) return } - openlog.Info(c, "get_wallet ok balance=%d frozen=%d", + openlog.Debug(c, "get_wallet ok balance=%d frozen=%d", wallet.AvailableBalance, wallet.FrozenBalance) response.OK(c, wallet) } @@ -168,7 +168,7 @@ func (h *OpenV1Handler) GetWallet(c *gin.Context) { func (h *OpenV1Handler) GetDeliveryLink(c *gin.Context) { openlog.SetAction(c, openlog.ActionQuery) orderNo := c.Param("order_no") - openlog.Info(c, "delivery_link start order_no=%s", orderNo) + openlog.Debug(c, "delivery_link start order_no=%s", orderNo) link, err := h.deliverySvc.GetOrCreateDeliveryLink(middleware.GetMerchantID(c), orderNo, requestBaseURL(c)) if err != nil { openlog.Warn(c, "delivery_link fail order_no=%s err=%v", orderNo, err) @@ -189,7 +189,7 @@ func (h *OpenV1Handler) GetDeliveryLink(c *gin.Context) { func (h *OpenV1Handler) GetDeliveryOrder(c *gin.Context) { openlog.SetAction(c, openlog.ActionQuery) orderNo := c.Param("order_no") - openlog.Info(c, "delivery_get start order_no=%s", orderNo) + openlog.Debug(c, "delivery_get start order_no=%s", orderNo) order, err := h.deliverySvc.GetMerchantOrder(middleware.GetMerchantID(c), orderNo) if err != nil { openlog.Warn(c, "delivery_get fail order_no=%s err=%v", orderNo, err) @@ -239,7 +239,7 @@ func (h *OpenV1Handler) GetDeliveryBindResult(c *gin.Context) { openlog.SetAction(c, openlog.ActionQuery) orderNo := c.Param("order_no") bindUUID := c.Query("bind_uuid") - openlog.Info(c, "delivery_bind_result start order_no=%s bind_uuid=%s", orderNo, bindUUID) + openlog.Debug(c, "delivery_bind_result start order_no=%s bind_uuid=%s", orderNo, bindUUID) result, err := h.deliverySvc.GetBindResult(middleware.GetMerchantID(c), orderNo, bindUUID) if err != nil { openlog.Warn(c, "delivery_bind_result fail order_no=%s err=%v", orderNo, err) diff --git a/backend/internal/middleware/open_auth.go b/backend/internal/middleware/open_auth.go index e237383..8ef7199 100644 --- a/backend/internal/middleware/open_auth.go +++ b/backend/internal/middleware/open_auth.go @@ -151,7 +151,7 @@ func OpenAuth(cfg OpenAuthConfig) gin.HandlerFunc { c.Set(openlog.CtxAPIKey, appKey) _ = cfg.DB.Model(&model.APIClient{}).Where("id = ?", client.ID).Update("last_used_at", now).Error - openlog.Info(c, "open_auth ok app_key=%s merchant_id=%d method=%s path=%s body_size=%d", + openlog.Debug(c, "open_auth ok app_key=%s merchant_id=%d method=%s path=%s body_size=%d", openlog.MaskKey(appKey), client.MerchantID, method, path, len(bodyBytes)) c.Next() } diff --git a/backend/internal/middleware/source_open_auth.go b/backend/internal/middleware/source_open_auth.go index 9a5e584..639149a 100644 --- a/backend/internal/middleware/source_open_auth.go +++ b/backend/internal/middleware/source_open_auth.go @@ -121,7 +121,7 @@ func SourceOpenAuth(cfg SourceOpenAuthConfig) gin.HandlerFunc { return } - openlog.Info(c, "source_open_auth ok method=%s path=%s body_size=%d", + openlog.Debug(c, "source_open_auth ok method=%s path=%s body_size=%d", c.Request.Method, c.Request.URL.Path, len(bodyBytes)) c.Next() } diff --git a/backend/internal/pkg/applog/applog.go b/backend/internal/pkg/applog/applog.go index 53e81cb..aefcfce 100644 --- a/backend/internal/pkg/applog/applog.go +++ b/backend/internal/pkg/applog/applog.go @@ -8,12 +8,114 @@ import ( "path/filepath" "strings" "sync" + "sync/atomic" "time" "github.com/gin-gonic/gin" "gorm.io/gorm/logger" ) +// Level 定义日志级别 +type Level int32 + +const ( + LevelDebug Level = iota + LevelInfo + LevelWarn + LevelError +) + +func (l Level) String() string { + switch l { + case LevelDebug: + return "DEBUG" + case LevelInfo: + return "INFO" + case LevelWarn: + return "WARN" + case LevelError: + return "ERROR" + default: + return "INFO" + } +} + +// ParseLevel 将字符串解析为日志级别，默认 INFO +func ParseLevel(s string) Level { + switch strings.ToLower(strings.TrimSpace(s)) { + case "debug": + return LevelDebug + case "warn", "warning": + return LevelWarn + case "error": + return LevelError + case "info": + return LevelInfo + default: + return LevelInfo + } +} + +var currentLevel int32 = int32(LevelInfo) + +// SetLevel 设置全局日志过滤级别 +func SetLevel(lvl string) { + parsed := ParseLevel(lvl) + atomic.StoreInt32(¤tLevel, int32(parsed)) +} + +// GetLevel 获取当前日志级别 +func GetLevel() Level { + return Level(atomic.LoadInt32(¤tLevel)) +} + +// IsDebug 是否允许输出 DEBUG 级别日志 +func IsDebug() bool { + return GetLevel() <= LevelDebug +} + +// IsInfo 是否允许输出 INFO 级别日志 +func IsInfo() bool { + return GetLevel() <= LevelInfo +} + +// IsWarn 是否允许输出 WARN 级别日志 +func IsWarn() bool { + return GetLevel() <= LevelWarn +} + +// Debugf 输出 DEBUG 级别日志 +func Debugf(format string, args ...any) { + if GetLevel() > LevelDebug { + return + } + log.Printf("[DEBUG] "+format, args...) +} + +// Infof 输出 INFO 级别日志 +func Infof(format string, args ...any) { + if GetLevel() > LevelInfo { + return + } + log.Printf("[INFO] "+format, args...) +} + +// Warnf 输出 WARN 级别日志 +func Warnf(format string, args ...any) { + if GetLevel() > LevelWarn { + return + } + log.Printf("[WARN] "+format, args...) +} + +// Errorf 输出 ERROR 级别日志 +func Errorf(format string, args ...any) { + if GetLevel() > LevelError { + return + } + log.Printf("[ERROR] "+format, args...) +} + // logRetainDays 保留最近多少天的日志文件；<=0 不清理。 var logRetainDays = 30 @@ -142,13 +244,15 @@ func Setup(logFile string) (*os.File, error) { log.SetOutput(mw) log.SetFlags(log.LstdFlags | log.Lmicroseconds) - // Gin access / recovery 日志 + // 禁用 Gin 的 ANSI 彩色输出，避免在日志文件中留下乱码转义字符 + gin.DisableConsoleColor() gin.DefaultWriter = mw gin.DefaultErrorWriter = mw if logFile != "" { abs, _ := filepath.Abs(logFile) - log.Printf("[applog] 日志按天分割输出到 %s-YYYYMMDD.log（保留 %d 天）", strings.TrimSuffix(abs, filepath.Ext(abs)), logRetainDays) + Infof("[applog] 日志按天分割输出到 %s-YYYYMMDD.log（保留 %d 天，级别: %s）", + strings.TrimSuffix(abs, filepath.Ext(abs)), logRetainDays, GetLevel()) } return f, nil } @@ -169,3 +273,4 @@ func NewGormLogger(mode string) logger.Interface { }, ) } + diff --git a/backend/internal/pkg/applog/applog_test.go b/backend/internal/pkg/applog/applog_test.go index 5f010e5..e62bc19 100644 --- a/backend/internal/pkg/applog/applog_test.go +++ b/backend/internal/pkg/applog/applog_test.go @@ -1,47 +1,74 @@ package applog import ( - "os" - "path/filepath" + "bytes" + "log" + "strings" "testing" - "time" ) -func TestDailyFileWriterRotatesAndCleans(t *testing.T) { - dir := t.TempDir() - logFile := filepath.Join(dir, "app.log") - - w, err := newDailyFileWriter(logFile) - if err != nil { - t.Fatalf("new writer: %v", err) - } - defer w.Close() - - // 写入当天日志，文件应按 app-YYYYMMDD.log 命名 - today := time.Now().Format("20060102") - if _, err := w.Write([]byte("line1\n")); err != nil { - t.Fatalf("write: %v", err) - } - todayPath := filepath.Join(dir, "app-"+today+".log") - if _, err := os.Stat(todayPath); err != nil { - t.Fatalf("today log file missing: %v", err) - } - // 旧格式 app.log 不应被创建 - if _, err := os.Stat(logFile); err == nil { - t.Fatalf("old-style app.log should not be created") +func TestParseLevel(t *testing.T) { + tests := []struct { + input string + expected Level + }{ + {"debug", LevelDebug}, + {"DEBUG", LevelDebug}, + {"info", LevelInfo}, + {"INFO", LevelInfo}, + {"warn", LevelWarn}, + {"warning", LevelWarn}, + {"WARN", LevelWarn}, + {"error", LevelError}, + {"ERROR", LevelError}, + {"unknown", LevelInfo}, + {"", LevelInfo}, } - // 构造过期文件，cleanup 应删除（保留 30 天，这里用 3 天验证） - old := filepath.Join(dir, "app-20260701.log") - if err := os.WriteFile(old, []byte("old"), 0o644); err != nil { - t.Fatalf("create old file: %v", err) - } - w.cleanup(time.Now()) - if _, err := os.Stat(old); err == nil { - t.Fatalf("old log file should be cleaned") - } - // 当天的文件应保留 - if _, err := os.Stat(todayPath); err != nil { - t.Fatalf("today log file should be kept") + for _, tc := range tests { + got := ParseLevel(tc.input) + if got != tc.expected { + t.Errorf("ParseLevel(%q) = %v, want %v", tc.input, got, tc.expected) + } + } +} + +func TestLogLevelFiltering(t *testing.T) { + var buf bytes.Buffer + log.SetOutput(&buf) + defer log.SetOutput(log.Writer()) + + SetLevel("warn") + + buf.Reset() + Debugf("this is debug: %d", 1) + if buf.Len() > 0 { + t.Errorf("expected debug to be filtered out, got %q", buf.String()) + } + + buf.Reset() + Infof("this is info: %d", 2) + if buf.Len() > 0 { + t.Errorf("expected info to be filtered out, got %q", buf.String()) + } + + buf.Reset() + Warnf("this is warn: %d", 3) + if !strings.Contains(buf.String(), "[WARN] this is warn: 3") { + t.Errorf("expected warn to be logged, got %q", buf.String()) + } + + buf.Reset() + Errorf("this is error: %d", 4) + if !strings.Contains(buf.String(), "[ERROR] this is error: 4") { + t.Errorf("expected error to be logged, got %q", buf.String()) + } + + // Now switch to debug + SetLevel("debug") + buf.Reset() + Debugf("debug now visible") + if !strings.Contains(buf.String(), "[DEBUG] debug now visible") { + t.Errorf("expected debug to be logged after SetLevel(debug), got %q", buf.String()) } } diff --git a/backend/internal/pkg/openlog/openlog.go b/backend/internal/pkg/openlog/openlog.go index 763d403..8ca2ace 100644 --- a/backend/internal/pkg/openlog/openlog.go +++ b/backend/internal/pkg/openlog/openlog.go @@ -2,10 +2,11 @@ package openlog import ( "fmt" - "log" "strings" "time" + "affiliate_dash/internal/pkg/applog" + "github.com/gin-gonic/gin" "github.com/google/uuid" ) @@ -45,7 +46,7 @@ var Enabled bool func Init(enabled bool) { Enabled = enabled if enabled { - log.Printf("[open] 开放接口调试日志已开启 (OPEN_API_DEBUG)") + applog.Infof("[open] 开放接口调试日志已开启 (OPEN_API_DEBUG)") } } @@ -104,15 +105,17 @@ func APITypeFromSide(side string) string { } func IsDebug(c *gin.Context) bool { - if !Enabled { - return false + if applog.IsDebug() || Enabled { + return true } - if v, ok := c.Get(CtxDebug); ok { - if b, ok := v.(bool); ok { - return b + if c != nil { + if v, ok := c.Get(CtxDebug); ok { + if b, ok := v.(bool); ok { + return b + } } } - return Enabled + return false } // MaskKey 脱敏 api_key：保留前缀与后 4 位 @@ -145,7 +148,10 @@ func Truncate(s string, max int) string { return s[:max] + fmt.Sprintf("...(%d bytes)", len(s)) } -func Prefix(c *gin.Context) string { +func Tag(c *gin.Context) string { + if c == nil { + return "open" + } side, _ := c.Get(CtxSide) apiType, _ := c.Get(CtxAPIType) action, _ := c.Get(CtxAction) @@ -158,32 +164,37 @@ func Prefix(c *gin.Context) string { } else if sideText != "" { tag += "." + sideText } - if actionText != "" { + if actionText != "" && actionText != ActionUnknown { tag += "." + actionText } - fields := "" - if apiTypeText != "" { - fields += fmt.Sprintf(" api_type=%s", apiTypeText) - } - if actionText != "" { - fields += fmt.Sprintf(" action=%s", actionText) - } - return fmt.Sprintf("[%s] req_id=%s%s ", tag, GetReqID(c), fields) + return tag } -func Info(c *gin.Context, format string, args ...interface{}) { +func Prefix(c *gin.Context) string { + return fmt.Sprintf("[%s] req_id=%s ", Tag(c), GetReqID(c)) +} + +// Debug 输出开放接口调试日志（高频查询、鉴权成功等），在 DEBUG 级别或 OPEN_API_DEBUG 开启时输出 +func Debug(c *gin.Context, format string, args ...interface{}) { if !IsDebug(c) { return } - log.Printf(Prefix(c)+format, args...) + applog.Debugf(Prefix(c)+format, args...) } +// Info 输出开放接口核心业务生命周期事件日志（下单、发货提交、取消、回调等） +func Info(c *gin.Context, format string, args ...interface{}) { + applog.Infof(Prefix(c)+format, args...) +} + +// Warn 输出开放接口业务告警/客户端参数错误日志 func Warn(c *gin.Context, format string, args ...interface{}) { - // 鉴权失败等也值得在 debug 时打出 - if !Enabled { - return - } - log.Printf(Prefix(c)+format, args...) + applog.Warnf(Prefix(c)+format, args...) +} + +// Error 输出开放接口系统故障或下游服务异常日志 +func Error(c *gin.Context, format string, args ...interface{}) { + applog.Errorf(Prefix(c)+format, args...) } func Elapsed(c *gin.Context) time.Duration { diff --git a/backend/internal/pkg/openlog/openlog_test.go b/backend/internal/pkg/openlog/openlog_test.go index 7f71035..38026b0 100644 --- a/backend/internal/pkg/openlog/openlog_test.go +++ b/backend/internal/pkg/openlog/openlog_test.go @@ -15,7 +15,7 @@ func TestPrefixIncludesSideAndAction(t *testing.T) { SetScope(c, SideSource, ActionPush) got := Prefix(c) - want := "[open.source_open_v1.push] req_id=req123 api_type=source_open_v1 action=push " + want := "[open.source_open_v1.push] req_id=req123 " if got != want { t.Fatalf("prefix mismatch: got %q want %q", got, want) } diff --git a/backend/internal/router/router.go b/backend/internal/router/router.go index 624cb9e..77e9ec8 100644 --- a/backend/internal/router/router.go +++ b/backend/internal/router/router.go @@ -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) } } diff --git a/backend/internal/router/router_test.go b/backend/internal/router/router_test.go index 616271e..45d9d69 100644 --- a/backend/internal/router/router_test.go +++ b/backend/internal/router/router_test.go @@ -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()) + } +} diff --git a/backend/internal/service/callback.go b/backend/internal/service/callback.go index b4ae3ea..8b8659c 100644 --- a/backend/internal/service/callback.go +++ b/backend/internal/service/callback.go @@ -10,13 +10,13 @@ import ( "errors" "fmt" "io" - "log" "net/http" "net/url" "strings" "time" "affiliate_dash/internal/model" + "affiliate_dash/internal/pkg/applog" "affiliate_dash/internal/pkg/timeutil" "github.com/google/uuid" @@ -325,13 +325,13 @@ func (s *CallbackService) dispatchOne(ctx context.Context, id uint) (bool, bool, resp, err := s.httpClient.Do(req) if err != nil { - log.Printf("[callback] push fail event=%s event_id=%s merchant_id=%d url=%s err=%s", delivery.Event, delivery.EventID, delivery.MerchantID, delivery.CallbackSubscription.URL, truncateCallbackError(err.Error())) + applog.Warnf("[callback] push fail event=%s event_id=%s merchant_id=%d url=%s err=%s", delivery.Event, delivery.EventID, delivery.MerchantID, delivery.CallbackSubscription.URL, truncateCallbackError(err.Error())) return false, true, s.recordCallbackFailure(delivery, 0, truncateCallbackError(err.Error())) } defer resp.Body.Close() body, _ := io.ReadAll(io.LimitReader(resp.Body, 4096)) if resp.StatusCode >= http.StatusOK && resp.StatusCode < http.StatusMultipleChoices { - log.Printf("[callback] push ok event=%s event_id=%s merchant_id=%d url=%s status=%d", delivery.Event, delivery.EventID, delivery.MerchantID, delivery.CallbackSubscription.URL, resp.StatusCode) + applog.Infof("[callback] push ok event=%s event_id=%s merchant_id=%d url=%s status=%d", delivery.Event, delivery.EventID, delivery.MerchantID, delivery.CallbackSubscription.URL, resp.StatusCode) return true, true, s.db.Model(&model.CallbackDelivery{}).Where("id = ?", delivery.ID).Updates(map[string]interface{}{ "status": model.CallbackDeliveryDelivered, "attempts": delivery.Attempts + 1, @@ -340,7 +340,7 @@ func (s *CallbackService) dispatchOne(ctx context.Context, id uint) (bool, bool, "delivered_at": time.Now(), }).Error } - log.Printf("[callback] push fail event=%s event_id=%s merchant_id=%d url=%s status=%d body=%s", delivery.Event, delivery.EventID, delivery.MerchantID, delivery.CallbackSubscription.URL, resp.StatusCode, truncateCallbackError(string(body))) + applog.Warnf("[callback] push fail event=%s event_id=%s merchant_id=%d url=%s status=%d body=%s", delivery.Event, delivery.EventID, delivery.MerchantID, delivery.CallbackSubscription.URL, resp.StatusCode, truncateCallbackError(string(body))) return false, true, s.recordCallbackFailure(delivery, resp.StatusCode, string(body)) } @@ -367,9 +367,9 @@ func (s *CallbackService) Run(ctx context.Context) { for { successes, failures, err := s.DispatchDue(ctx, 50) if err != nil { - log.Printf("[callback] dispatch error: %v", err) + applog.Errorf("[callback] dispatch error: %v", err) } else if successes > 0 || failures > 0 { - log.Printf("[callback] dispatch done successes=%d failures=%d", successes, failures) + applog.Infof("[callback] dispatch done successes=%d failures=%d", successes, failures) } select { case <-ctx.Done(): diff --git a/backend/internal/service/fulfillment_timeout.go b/backend/internal/service/fulfillment_timeout.go index 0d6c87e..666da70 100644 --- a/backend/internal/service/fulfillment_timeout.go +++ b/backend/internal/service/fulfillment_timeout.go @@ -4,10 +4,10 @@ import ( "context" "errors" "fmt" - "log" "time" "affiliate_dash/internal/model" + "affiliate_dash/internal/pkg/applog" "affiliate_dash/internal/pkg/timeutil" "gorm.io/gorm" @@ -116,9 +116,9 @@ func (s *FulfillmentService) RunProcessingTimeoutMonitor(ctx context.Context, ti for { changed, err := s.MarkProcessingTimeouts(timeout, 50) if err != nil { - log.Printf("[fulfillment] timeout scan error: %v", err) + applog.Errorf("[fulfillment] timeout scan error: %v", err) } else if changed > 0 { - log.Printf("[fulfillment] timeout scan marked failed count=%d", changed) + applog.Warnf("[fulfillment] timeout scan marked failed count=%d", changed) } select { case <-ctx.Done(): diff --git a/backend/internal/service/recharge.go b/backend/internal/service/recharge.go index 7b0e5d2..8928f49 100644 --- a/backend/internal/service/recharge.go +++ b/backend/internal/service/recharge.go @@ -6,7 +6,6 @@ import ( "errors" "fmt" "io" - "log" "net/http" "os" "path/filepath" @@ -15,6 +14,7 @@ import ( "time" "affiliate_dash/internal/model" + "affiliate_dash/internal/pkg/applog" "affiliate_dash/internal/pkg/timeutil" "github.com/google/uuid" @@ -372,7 +372,7 @@ func (s *RechargeService) CheckLowBalanceAndNotify(merchantID uint) { continue } if err := sendChannelMessage(channel, "余额告警", content); err != nil { - log.Printf("低余额告警推送失败 merchant=%d channel=%d: %v", merchantID, channel.ID, err) + applog.Errorf("[recharge] 低余额告警推送失败 merchant=%d channel=%d: %v", merchantID, channel.ID, err) continue } sent = true