From a0f025aa96e9a1df435b39324b7d31c8332a03a8 Mon Sep 17 00:00:00 2001 From: ddcat666 <26564566+ddcat666@users.noreply.github.com> Date: Wed, 30 Sep 2026 03:33:34 +0800 Subject: [PATCH] =?UTF-8?q?feat(platform):=20=E6=97=A5=E5=BF=97=E7=AE=A1?= =?UTF-8?q?=E7=90=86=20-=20=E7=BB=9F=E4=B8=80=E6=97=A5=E5=BF=97=E5=87=BA?= =?UTF-8?q?=E5=8F=A3=E5=B9=B6=E5=B1=8F=E8=94=BD=E6=9F=A5=E8=AF=A2=E4=B8=8E?= =?UTF-8?q?=20Agent=20=E6=B5=81=E5=BC=8F=E4=BA=8B=E4=BB=B6=E6=97=A5?= =?UTF-8?q?=E5=BF=97?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 新增 internal/logging,slog、标准库 log、GORM 与 Gin 访问日志共用同一 Handler,由 CANVAS_LOG_LEVEL / CANVAS_LOG_FORMAT 控制。info 级别不再输出成功的查询类请求、成功 SQL、message_end 等 Agent 流式事件和常规画布自动保存;4xx/5xx、慢请求、慢 SQL、SQL 失败与 panic 仍会记录,SQL 不内联参数值。 --- .env.example | 6 + backend/cmd/server/main.go | 20 ++- backend/internal/app/cloud_agent.go | 4 +- .../app/cloud_agent_pi_canvas_engines.go | 22 +-- .../app/cloud_agent_pi_coordinator.go | 15 +- .../internal/app/cloud_agent_pi_helpers.go | 8 +- backend/internal/app/cloud_agent_step_hash.go | 6 +- backend/internal/app/model_catalog.go | 12 +- .../internal/app/resource_deletion_worker.go | 5 +- backend/internal/database/database.go | 6 +- backend/internal/handler/user_data.go | 14 +- backend/internal/logging/gorm.go | 102 +++++++++++ backend/internal/logging/http.go | 111 ++++++++++++ backend/internal/logging/logging.go | 165 ++++++++++++++++++ backend/internal/logging/logging_test.go | 134 ++++++++++++++ docker-compose.deploy.yml | 2 + docker-compose.dev.yml | 1 + docker-compose.local.yml | 2 + docker-compose.server.yml | 2 + docker-compose.yml | 2 + docs/content/docs/progress/pending-test.mdx | 7 + 21 files changed, 602 insertions(+), 44 deletions(-) create mode 100644 backend/internal/logging/gorm.go create mode 100644 backend/internal/logging/http.go create mode 100644 backend/internal/logging/logging.go create mode 100644 backend/internal/logging/logging_test.go diff --git a/.env.example b/.env.example index d050c64b1..48b1dc5b8 100644 --- a/.env.example +++ b/.env.example @@ -38,3 +38,9 @@ CANVAS_UPDATER_SOCKET_DIR=/run/open-ai-canvas-updater # CANVAS_POSTGRES_DATA_PATH=./postgres-data # CANVAS_REDIS_DATA_PATH=./redis-data # CANVAS_HTTP_PORT=3000 + +# 后端日志:info 级别不输出成功的查询请求与 Agent 流式事件;排障时临时改为 debug。 +# CANVAS_LOG_LEVEL=info +# CANVAS_LOG_FORMAT=text +# CANVAS_LOG_SLOW_REQUEST=2s +# CANVAS_LOG_SLOW_SQL=500ms diff --git a/backend/cmd/server/main.go b/backend/cmd/server/main.go index d6f6e2c6e..d05536655 100644 --- a/backend/cmd/server/main.go +++ b/backend/cmd/server/main.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "log" + "log/slog" "net" "net/http" "net/url" @@ -17,6 +18,7 @@ import ( "infinite-canvas/backend/internal/database" "infinite-canvas/backend/internal/handler" + "infinite-canvas/backend/internal/logging" "infinite-canvas/backend/internal/repository" "infinite-canvas/backend/internal/service" "infinite-canvas/backend/internal/updaterclient" @@ -25,6 +27,11 @@ import ( ) func main() { + logConfig, err := logging.ConfigFromEnv() + if err != nil { + log.Fatal(err) + } + logging.Setup(logConfig) ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) defer stop() if err := run(ctx); err != nil { @@ -95,14 +102,13 @@ func run(ctx context.Context) error { return err } if summary, err := svc.MigrateLegacyStorage(); err != nil { - log.Printf("storage migration skipped after error: %v", err) + slog.Warn("storage migration skipped after error", "error", err) } else if summary.Backup != "" { - log.Printf("storage migration completed: tasks=%d assets=%d projects=%d backup=%s", summary.Tasks, summary.Assets, summary.Projects, summary.Backup) + slog.Info("storage migration completed", "tasks", summary.Tasks, "assets", summary.Assets, "projects", summary.Projects, "backup", summary.Backup) } r := gin.New() - r.Use(gin.LoggerWithFormatter(func(param gin.LogFormatterParams) string { - return fmt.Sprintf("%s - [%s] \"%s %s\" %d %s %s\n", param.ClientIP, param.TimeStamp.Format(time.RFC3339), param.Method, redactCanvasSharePath(param.Path), param.StatusCode, param.Latency, param.ErrorMessage) - }), gin.Recovery()) + // 访问日志:成功的查询类请求只在 debug 级别输出,避免轮询和列表查询把日志打爆。 + r.Use(logging.AccessLog(redactCanvasSharePath), logging.Recovery()) r.Use(handler.RequestCorrelationMiddleware()) corsMiddleware, err := cors() if err != nil { @@ -133,7 +139,7 @@ func run(ctx context.Context) error { status.markStarted() serveErr := make(chan error, 1) go func() { serveErr <- httpServer.Serve(listener) }() - log.Printf("backend listening on %s", addr) + slog.Info("backend listening", "addr", addr) var serveFailure error select { @@ -163,7 +169,7 @@ func run(ctx context.Context) error { if err := errors.Join(shutdownFailures...); err != nil { return err } - log.Printf("backend stopped gracefully") + slog.Info("backend stopped gracefully") return nil } diff --git a/backend/internal/app/cloud_agent.go b/backend/internal/app/cloud_agent.go index 1262d35d2..cbc6798bc 100644 --- a/backend/internal/app/cloud_agent.go +++ b/backend/internal/app/cloud_agent.go @@ -5,7 +5,7 @@ import ( "encoding/hex" "encoding/json" "errors" - "log" + "log/slog" "math" "strings" "time" @@ -403,7 +403,7 @@ func (s *Service) CreateCloudAgentRun(userID string, req CloudAgentRequest, pare return nil, err } if superseded { - log.Printf("agent run %s cannot resume after a contract change; continuing in a new turn", parentID) + slog.Info("agent run cannot resume after a contract change; continuing in a new turn", "run", parentID) } else if !cloudAgentRunTerminal(parentRun.Status) || parentRun.CleanupPending { return nil, kernel.NewAppError(409, "上一轮 Agent 尚未结束") } diff --git a/backend/internal/app/cloud_agent_pi_canvas_engines.go b/backend/internal/app/cloud_agent_pi_canvas_engines.go index f9641f624..7019db447 100644 --- a/backend/internal/app/cloud_agent_pi_canvas_engines.go +++ b/backend/internal/app/cloud_agent_pi_canvas_engines.go @@ -5,7 +5,7 @@ import ( "encoding/json" "errors" "fmt" - "log" + "log/slog" "math" "sort" "strings" @@ -510,7 +510,7 @@ func (e *CanvasSearchEngine) generateHighlight(node model.CanvasNode, query Canv // handleMessageStart 处理消息开始事件 func (s *Service) handleMessageStart(userID, runID string, data map[string]any) (any, error) { // 记录消息开始 - log.Printf("[Agent] message_start run=%s", runID) + slog.Debug("agent message_start", "run", runID) // 更新运行状态 run, err := s.repo.CloudAgent(userID, runID) @@ -537,14 +537,14 @@ func (s *Service) handleMessageStart(userID, runID string, data map[string]any) func (s *Service) handleMessageDelta(userID, runID string, data map[string]any) (any, error) { delta, _ := data["delta"].(string) messageID, _ := data["messageId"].(string) - log.Printf("[Agent] message_delta run=%s messageId=%s len=%d", runID, messageID, len(delta)) + slog.Debug("agent message_delta", "run", runID, "message_id", messageID, "len", len(delta)) // 推送实时增量到前端 if err := s.broadcastAgentEvent(userID, runID, "message_delta", map[string]any{ "delta": delta, "messageId": messageID, }); err != nil { - log.Printf("[Agent] failed to broadcast message_delta: %v", err) + slog.Warn("agent message_delta broadcast failed", "run", runID, "error", err) } return map[string]any{"ok": true}, nil @@ -552,19 +552,19 @@ func (s *Service) handleMessageDelta(userID, runID string, data map[string]any) // handleMessageEnd 处理消息结束事件(关键修复点) func (s *Service) handleMessageEnd(userID, runID string, data map[string]any) (any, error) { - log.Printf("[Agent] message_end run=%s data=%+v", runID, data) + slog.Debug("agent message_end", "run", runID, "role", data["role"]) // 检查消息角色,防止将用户消息误认为助手消息 role, _ := data["role"].(string) if role == "user" { // 这是用户消息结束,不是助手响应,直接返回 - log.Printf("[Agent] ignoring user message_end run=%s", runID) + slog.Debug("agent message_end ignored", "run", runID, "role", "user") return map[string]any{"ok": true, "ignored": true, "reason": "user message"}, nil } // 只处理助手消息结束 if role != "assistant" { - log.Printf("[Agent] ignoring non-assistant message_end run=%s role=%s", runID, role) + slog.Debug("agent message_end ignored", "run", runID, "role", role) return map[string]any{"ok": true, "ignored": true, "reason": fmt.Sprintf("non-assistant role: %s", role)}, nil } @@ -585,7 +585,7 @@ func (s *Service) handleMessageEnd(userID, runID string, data map[string]any) (a // 计数真实的助手响应 state.PiAssistantResponses++ - log.Printf("[Agent] assistant response completed run=%s count=%d", runID, state.PiAssistantResponses) + slog.Debug("agent assistant response completed", "run", runID, "count", state.PiAssistantResponses) if err := s.saveCloudAgentRuntimeState(userID, runID, &state); err != nil { return nil, err @@ -597,7 +597,7 @@ func (s *Service) handleMessageEnd(userID, runID string, data map[string]any) (a // handleToolCall 处理工具调用事件 func (s *Service) handleToolCall(userID, runID string, data map[string]any) (any, error) { toolName, _ := data["toolName"].(string) - log.Printf("[Agent] tool_call run=%s tool=%s", runID, toolName) + slog.Debug("agent tool_call", "run", runID, "tool", toolName) return map[string]any{"ok": true}, nil } @@ -605,7 +605,7 @@ func (s *Service) handleToolCall(userID, runID string, data map[string]any) (any // handleError 处理错误事件 func (s *Service) handleError(userID, runID string, data map[string]any) (any, error) { errorMsg, _ := data["error"].(string) - log.Printf("[Agent] error run=%s error=%s", runID, errorMsg) + slog.Warn("agent runtime error", "run", runID, "error", errorMsg) // 更新运行状态为失败 run, err := s.repo.CloudAgent(userID, runID) @@ -687,7 +687,7 @@ func (s *Service) updatePiRunWithStep(userID, runID string, revision int64, step // routeStandardTool 路由标准工具(非画布工具) func (s *Service) routeStandardTool(ctx context.Context, userID, runID, toolName string, payload map[string]json.RawMessage) (any, error) { - log.Printf("[Agent] routing standard tool: %s", toolName) + slog.Debug("agent routing standard tool", "run", runID, "tool", toolName) // 将参数从 json.RawMessage 转换为 map[string]any args := make(map[string]any) diff --git a/backend/internal/app/cloud_agent_pi_coordinator.go b/backend/internal/app/cloud_agent_pi_coordinator.go index e92ef8202..5fd3fbff7 100644 --- a/backend/internal/app/cloud_agent_pi_coordinator.go +++ b/backend/internal/app/cloud_agent_pi_coordinator.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "log" + "log/slog" "os" "path/filepath" "strings" @@ -380,7 +381,7 @@ type EnhancedPiRequestParams struct { // buildEnhancedPiRequest 构建增强的 Pi 请求(核心方法) func (s *Service) buildEnhancedPiRequest(ctx context.Context, params EnhancedPiRequestParams) (cloudAgentPiProcessRequest, error) { - log.Printf("[Agent] building enhanced request for canvas=%s", params.CanvasID) + slog.Debug("agent building request", "canvas", params.CanvasID) // 1. 构建工具列表(包括画布工具) tools := s.buildCompletePiTools(params.Canonical.Tools) @@ -389,7 +390,7 @@ func (s *Service) buildEnhancedPiRequest(ctx context.Context, params EnhancedPiR skillPaths := s.buildSkillPaths(params.RuntimeState.Skills) enabledSkills := s.buildSkillManifests(params.RuntimeState.Skills) - log.Printf("[Agent] enabled skills: %d", len(enabledSkills)) + slog.Debug("agent enabled skills", "count", len(enabledSkills)) // 3. 构建 Profile 配置 profile := s.buildProfileConfig(params.RuntimeState.Profile) @@ -409,11 +410,11 @@ func (s *Service) buildEnhancedPiRequest(ctx context.Context, params EnhancedPiR return cloudAgentPiProcessRequest{}, fmt.Errorf("marshal canvas: %w", err) } - log.Printf("[Agent] canvas intelligence: nodes=%d, focus=%d, relationships=%d, clusters=%d", + slog.Debug("agent canvas intelligence", "nodes", enhancedCanvas.Snapshot.TotalNodes, - len(enhancedCanvas.Snapshot.FocusNodes), - len(enhancedCanvas.Snapshot.Relationships), - len(enhancedCanvas.Snapshot.Layout.Clusters)) + "focus", len(enhancedCanvas.Snapshot.FocusNodes), + "relationships", len(enhancedCanvas.Snapshot.Relationships), + "clusters", len(enhancedCanvas.Snapshot.Layout.Clusters)) // 6. 构建 Features 配置 features := s.buildFeaturesConfig(params.RuntimeState) @@ -461,7 +462,7 @@ func (s *Service) buildEnhancedPiRequest(ctx context.Context, params EnhancedPiR Model: modelConfig, } - log.Printf("[Agent] request built successfully") + slog.Debug("agent request built", "canvas", params.CanvasID) return request, nil } diff --git a/backend/internal/app/cloud_agent_pi_helpers.go b/backend/internal/app/cloud_agent_pi_helpers.go index d6e1ae569..9a9be1626 100644 --- a/backend/internal/app/cloud_agent_pi_helpers.go +++ b/backend/internal/app/cloud_agent_pi_helpers.go @@ -4,7 +4,7 @@ import ( "crypto/sha256" "encoding/hex" "fmt" - "log" + "log/slog" "infinite-canvas/backend/internal/model" ) @@ -191,17 +191,17 @@ func formatDuration(ms int64) string { // logPiAgentStep 记录 Pi Agent 步骤 func logPiAgentStep(runID, step, message string) { - log.Printf("[Agent Step] run=%s step=%s: %s", runID, step, message) + slog.Debug("agent step", "run", runID, "step", step, "message", message) } // logPiAgentError 记录 Pi Agent 错误 func logPiAgentError(runID string, err error) { - log.Printf("[Agent Error] run=%s: %v", runID, err) + slog.Warn("agent error", "run", runID, "error", err) } // logPiAgentMetric 记录 Pi Agent 指标 func logPiAgentMetric(runID, metric string, value interface{}) { - log.Printf("[Agent Metric] run=%s %s=%v", runID, metric, value) + slog.Debug("agent metric", "run", runID, "metric", metric, "value", value) } // Type Conversions diff --git a/backend/internal/app/cloud_agent_step_hash.go b/backend/internal/app/cloud_agent_step_hash.go index 6639a6fd2..25fa3e178 100644 --- a/backend/internal/app/cloud_agent_step_hash.go +++ b/backend/internal/app/cloud_agent_step_hash.go @@ -2,7 +2,7 @@ package app import ( "encoding/json" - "log" + "log/slog" "infinite-canvas/backend/internal/model" ) @@ -70,7 +70,7 @@ func (s *Service) cloudAgentRefreshStepSnapshotHash(run *model.CloudAgentExecuti return call } call = cloudAgentRewriteCallSnapshotHash(call, latest) - log.Printf("agent step hash filled: run=%s step=%d index=%d tool=%s", run.ID, state.Step, state.CallIndex, call.Function.Name) + slog.Debug("agent step hash filled", "run", run.ID, "step", state.Step, "index", state.CallIndex, "tool", call.Function.Name) return call } baseline := state.StepSnapshotHash @@ -118,6 +118,6 @@ func (s *Service) cloudAgentRefreshStepSnapshotHash(run *model.CloudAgentExecuti return call } call = cloudAgentRewriteCallSnapshotHash(call, latest) - log.Printf("agent step hash refreshed: run=%s step=%d index=%d tool=%s", run.ID, state.Step, state.CallIndex, call.Function.Name) + slog.Debug("agent step hash refreshed", "run", run.ID, "step", state.Step, "index", state.CallIndex, "tool", call.Function.Name) return call } diff --git a/backend/internal/app/model_catalog.go b/backend/internal/app/model_catalog.go index 289738a12..1d08078dc 100644 --- a/backend/internal/app/model_catalog.go +++ b/backend/internal/app/model_catalog.go @@ -3,8 +3,10 @@ package app import ( "encoding/json" "fmt" - "log" + "log/slog" + "time" + "infinite-canvas/backend/internal/logging" "infinite-canvas/backend/internal/model" ) @@ -111,7 +113,9 @@ func (s *Service) publicSystemChannelCatalog(intent *ModelRequestIntent) ([]Publ if intent != nil { matched, matchErr := s.channelModelMatchesIntent(&cm, intent) if matchErr != nil { - log.Printf("system channel model omitted from catalog id=%s: invalid capability: %v", cm.ID, matchErr) + if logging.Every("catalog-omit:"+cm.ID, 10*time.Minute) { + slog.Warn("system channel model omitted from catalog", "id", cm.ID, "reason", "invalid capability", "error", matchErr) + } continue } if !matched { @@ -121,7 +125,9 @@ func (s *Service) publicSystemChannelCatalog(intent *ModelRequestIntent) ([]Publ publicModel, sanitizeErr := s.sanitizeChannelModel(&cm) if sanitizeErr != nil { - log.Printf("system channel model omitted from catalog id=%s: %v", cm.ID, sanitizeErr) + if logging.Every("catalog-omit:"+cm.ID, 10*time.Minute) { + slog.Warn("system channel model omitted from catalog", "id", cm.ID, "error", sanitizeErr) + } continue } publicModels = append(publicModels, publicModel) diff --git a/backend/internal/app/resource_deletion_worker.go b/backend/internal/app/resource_deletion_worker.go index b52cb04de..f24a5df29 100644 --- a/backend/internal/app/resource_deletion_worker.go +++ b/backend/internal/app/resource_deletion_worker.go @@ -3,6 +3,7 @@ package app import ( "context" "log" + "log/slog" "math" "strings" "time" @@ -124,7 +125,7 @@ func (s *Service) cleanupDetachedUserResources(userID string, candidates []model if err := s.repo.DeleteDetachedResources(detached, deletionJobs); err != nil { return err } - log.Printf("detached resource cleanup: removed %d resource rows for user %s", len(detached), userID) + slog.Info("detached resource cleanup", "removed", len(detached), "user", userID) if len(deletionJobs) > 0 { s.runWorkerTask(func() { s.drainResourceDeletionJobs(len(deletionJobs)) }) } @@ -157,7 +158,7 @@ func (s *Service) cleanupExpiredArchivedAssets() { deleted++ } if deleted > 0 { - log.Printf("recycle bin cleanup: deleted %d expired assets (retention: %d days)", deleted, retentionDays) + slog.Info("recycle bin cleanup", "deleted", deleted, "retention_days", retentionDays) } } diff --git a/backend/internal/database/database.go b/backend/internal/database/database.go index 87f26418b..9d0533a3e 100644 --- a/backend/internal/database/database.go +++ b/backend/internal/database/database.go @@ -6,6 +6,8 @@ import ( "os" "strings" + "infinite-canvas/backend/internal/logging" + "gorm.io/driver/postgres" "gorm.io/driver/sqlite" "gorm.io/gorm" @@ -31,13 +33,13 @@ func Open(config Config) (*gorm.DB, error) { } dsn = config.DataDir + "/open_ai_canvas.db?_busy_timeout=5000&_journal_mode=WAL&_foreign_keys=on&_synchronous=NORMAL" } - return gorm.Open(sqlite.Open(dsn), &gorm.Config{}) + return gorm.Open(sqlite.Open(dsn), &gorm.Config{Logger: logging.GormLogger()}) case "postgres", "postgresql": dsn := strings.TrimSpace(config.DSN) if dsn == "" { return nil, errors.New("PostgreSQL 模式必须配置 DATABASE_URL") } - return gorm.Open(postgres.Open(dsn), &gorm.Config{}) + return gorm.Open(postgres.Open(dsn), &gorm.Config{Logger: logging.GormLogger()}) default: return nil, fmt.Errorf("不支持的数据库驱动:%s", driver) } diff --git a/backend/internal/handler/user_data.go b/backend/internal/handler/user_data.go index 3948eec11..ed4ef4f27 100644 --- a/backend/internal/handler/user_data.go +++ b/backend/internal/handler/user_data.go @@ -6,7 +6,7 @@ import ( "encoding/json" "errors" "fmt" - "log" + "log/slog" "net/http" "strconv" "strings" @@ -606,7 +606,7 @@ func RegisterUserDataRoutes(r *gin.RouterGroup, svc *service.Service) { failService(c, err) return } - log.Printf("canvas_restore request_id=%q trace_id=%q actor=%q canvas=%q snapshot=%q base_revision=%d revision=%d", RequestID(c), TraceID(c), user.ID, c.Param("id"), c.Param("snapshotId"), *req.Revision, project.Revision) + slog.Info("canvas_restore", "request_id", RequestID(c), "trace_id", TraceID(c), "actor", user.ID, "canvas", c.Param("id"), "snapshot", c.Param("snapshotId"), "base_revision", *req.Revision, "revision", project.Revision) ok(c, gin.H{"project": project}) }) r.PUT("/canvas-projects/:id", func(c *gin.Context) { @@ -657,7 +657,15 @@ func RegisterUserDataRoutes(r *gin.RouterGroup, svc *service.Service) { nodesBefore, nodesAfter = project.SaveAudit.NodesBefore, project.SaveAudit.NodesAfter } // Metadata only: never log prompts, media URLs, cookies, or the canvas payload. - log.Printf("canvas_save request_id=%q trace_id=%q actor=%q canvas=%q base_revision=%d revision=%d nodes_before=%d nodes_after=%d connections=%d status=%d", RequestID(c), TraceID(c), user.ID, identity.ID, baseRevision, project.Revision, nodesBefore, nodesAfter, len(audit.Connections), c.Writer.Status()) + // 自动保存非常频繁:常规保存只在 debug 输出;节点减少(可能丢数据)或保存失败才提升级别。 + level := slog.LevelDebug + switch { + case c.Writer.Status() >= http.StatusBadRequest: + level = slog.LevelWarn + case nodesBefore >= 0 && nodesAfter < nodesBefore: + level = slog.LevelInfo + } + slog.Log(c.Request.Context(), level, "canvas_save", "request_id", RequestID(c), "trace_id", TraceID(c), "actor", user.ID, "canvas", identity.ID, "base_revision", baseRevision, "revision", project.Revision, "nodes_before", nodesBefore, "nodes_after", nodesAfter, "connections", len(audit.Connections), "status", c.Writer.Status()) }() if err != nil { failService(c, err) diff --git a/backend/internal/logging/gorm.go b/backend/internal/logging/gorm.go new file mode 100644 index 000000000..919299157 --- /dev/null +++ b/backend/internal/logging/gorm.go @@ -0,0 +1,102 @@ +package logging + +import ( + "context" + "errors" + "log/slog" + "time" + + "gorm.io/gorm" + gormlogger "gorm.io/gorm/logger" +) + +// GormLogger 把 GORM 日志接入统一 Handler:成功的 SQL 一律不输出,只记录失败与慢查询。 +// SQL 以参数化形式输出(不内联参数值),避免密码哈希、token 等写进日志。 +func GormLogger() gormlogger.Interface { + return gormLogger{level: gormlogger.Warn} +} + +type gormLogger struct { + level gormlogger.LogLevel +} + +func (l gormLogger) LogMode(level gormlogger.LogLevel) gormlogger.Interface { + l.level = level + return l +} + +func (l gormLogger) Info(ctx context.Context, msg string, data ...any) { + if l.level >= gormlogger.Info { + slog.InfoContext(ctx, "gorm: "+msg, "data", data) + } +} + +func (l gormLogger) Warn(ctx context.Context, msg string, data ...any) { + if l.level >= gormlogger.Warn { + slog.WarnContext(ctx, "gorm: "+msg, "data", data) + } +} + +func (l gormLogger) Error(ctx context.Context, msg string, data ...any) { + if l.level >= gormlogger.Error { + slog.ErrorContext(ctx, "gorm: "+msg, "data", data) + } +} + +func (l gormLogger) Trace(ctx context.Context, begin time.Time, fc func() (string, int64), err error) { + if l.level <= gormlogger.Silent { + return + } + elapsed := time.Since(begin) + var level slog.Level + var msg string + switch { + case err != nil && isExpectedQueryError(err): + return + case err != nil: + if l.level < gormlogger.Error { + return + } + level, msg = slog.LevelWarn, "sql failed" + case slowSQLThreshold() > 0 && elapsed >= slowSQLThreshold(): + if l.level < gormlogger.Warn { + return + } + level, msg = slog.LevelWarn, "sql slow" + default: + return + } + if ctx == nil { + ctx = context.Background() + } + if !slog.Default().Enabled(ctx, level) { + return + } + sql, rows := fc() + attrs := []slog.Attr{ + slog.Int64("duration_ms", elapsed.Milliseconds()), + slog.Int64("rows", rows), + slog.String("sql", truncate(sql, 2000)), + } + if err != nil { + attrs = append(attrs, slog.String("error", err.Error())) + } + slog.LogAttrs(ctx, level, msg, attrs...) +} + +// ParamsFilter 让 GORM 在生成日志用的 SQL 时丢弃参数值。 +func (gormLogger) ParamsFilter(_ context.Context, sql string, _ ...any) (string, []any) { + return sql, nil +} + +// 查不到记录、请求取消属于正常业务分支,由调用方决定是否需要记录。 +func isExpectedQueryError(err error) bool { + return errors.Is(err, gorm.ErrRecordNotFound) || errors.Is(err, context.Canceled) +} + +func truncate(value string, limit int) string { + if len(value) <= limit { + return value + } + return value[:limit] + "...(truncated)" +} diff --git a/backend/internal/logging/http.go b/backend/internal/logging/http.go new file mode 100644 index 000000000..c78027be3 --- /dev/null +++ b/backend/internal/logging/http.go @@ -0,0 +1,111 @@ +package logging + +import ( + "io" + "log/slog" + "net/http" + "runtime/debug" + "strings" + "time" + + "github.com/gin-gonic/gin" +) + +// quietWriteSuffixes 是语义上只读、但用 POST 发出的高频路由(心跳、状态查询、批量读取)。 +// 与 GET 一样,成功时只在 debug 级别输出。 +var quietWriteSuffixes = []string{ + "/heartbeat", + "/query", + "/query-provider", + "/query-task", + "/checkout/refresh", + "/assets/batch", + "/announcements/read", + "/diagnostics/preview", + "/system-update/check", +} + +// AccessLog 替代 gin.Logger:成功的查询类请求(GET/HEAD/OPTIONS 与 quietWriteSuffixes)降为 debug, +// 写请求记 info,4xx 记 warn,5xx 记 error;超过慢请求阈值的非流式请求无论方法都记 warn。 +// redactPath 用于脱敏 URL 中的凭据段(例如分享 token),为 nil 时原样输出。 +func AccessLog(redactPath func(string) string) gin.HandlerFunc { + return func(c *gin.Context) { + start := time.Now() + c.Next() + latency := time.Since(start) + status := c.Writer.Status() + route := c.FullPath() + level := accessLevel(c.Request.Method, route, status, latency, isStreamResponse(c)) + ctx := c.Request.Context() + if !slog.Default().Enabled(ctx, level) { + return + } + path := c.Request.URL.Path + if redactPath != nil { + path = redactPath(path) + } + attrs := []slog.Attr{ + slog.String("method", c.Request.Method), + slog.String("path", path), + slog.Int("status", status), + slog.Int64("latency_ms", latency.Milliseconds()), + slog.String("ip", c.ClientIP()), + } + if requestID := c.Writer.Header().Get("X-Request-ID"); requestID != "" { + attrs = append(attrs, slog.String("request_id", requestID)) + } + if message := c.Errors.ByType(gin.ErrorTypePrivate).String(); message != "" { + attrs = append(attrs, slog.String("error", strings.TrimSpace(message))) + } + slog.LogAttrs(ctx, level, "http request", attrs...) + } +} + +func accessLevel(method, route string, status int, latency time.Duration, stream bool) slog.Level { + switch { + case status >= http.StatusInternalServerError: + return slog.LevelError + case status >= http.StatusBadRequest: + return slog.LevelWarn + } + if threshold := slowRequestThreshold(); threshold > 0 && !stream && latency >= threshold { + return slog.LevelWarn + } + if isQueryRequest(method, route) { + return slog.LevelDebug + } + return slog.LevelInfo +} + +func isQueryRequest(method, route string) bool { + switch method { + case http.MethodGet, http.MethodHead, http.MethodOptions: + return true + case http.MethodPost: + for _, suffix := range quietWriteSuffixes { + if strings.HasSuffix(route, suffix) { + return true + } + } + } + return false +} + +// SSE 与分块下载天然是长连接,耗时不代表慢。 +func isStreamResponse(c *gin.Context) bool { + return strings.Contains(c.Writer.Header().Get("Content-Type"), "text/event-stream") +} + +// Recovery 替代 gin.Recovery:panic 与堆栈进入统一日志,而不是直接写带颜色码的 stderr。 +func Recovery() gin.HandlerFunc { + return gin.CustomRecoveryWithWriter(io.Discard, func(c *gin.Context, recovered any) { + slog.ErrorContext(c.Request.Context(), "http panic recovered", + "method", c.Request.Method, + "route", c.FullPath(), + "request_id", c.Writer.Header().Get("X-Request-ID"), + "panic", recovered, + "stack", string(debug.Stack()), + ) + c.AbortWithStatus(http.StatusInternalServerError) + }) +} diff --git a/backend/internal/logging/logging.go b/backend/internal/logging/logging.go new file mode 100644 index 000000000..1e9c57d15 --- /dev/null +++ b/backend/internal/logging/logging.go @@ -0,0 +1,165 @@ +// Package logging 是后端唯一的日志出口。 +// +// slog、标准库 log、GORM 与 Gin 访问日志都经由同一个 slog Handler 输出,格式与级别由环境变量统一控制: +// +// CANVAS_LOG_LEVEL debug | info | warn | error(默认 info) +// CANVAS_LOG_FORMAT text | json(默认 text) +// CANVAS_LOG_SLOW_REQUEST API 慢请求阈值(默认 2s,0 关闭) +// CANVAS_LOG_SLOW_SQL 慢 SQL 阈值(默认 500ms,0 关闭) +// +// 约定:新代码直接使用 log/slog 并选择合适级别;查询、流式事件、轮询等高频路径只能用 Debug。 +// 存量 log.Printf 基本都在失败分支,Setup 后统一按 WARN 桥接进同一个 Handler。 +package logging + +import ( + "fmt" + "io" + "log/slog" + "os" + "strings" + "sync" + "time" +) + +const ( + EnvLevel = "CANVAS_LOG_LEVEL" + EnvFormat = "CANVAS_LOG_FORMAT" + EnvSlowRequest = "CANVAS_LOG_SLOW_REQUEST" + EnvSlowSQL = "CANVAS_LOG_SLOW_SQL" + + defaultSlowRequest = 2 * time.Second + defaultSlowSQL = 500 * time.Millisecond +) + +type Config struct { + Level slog.Level + JSON bool + SlowRequest time.Duration + SlowSQL time.Duration + Output io.Writer +} + +var ( + level = new(slog.LevelVar) + + settingsMu sync.RWMutex + slowRequest = defaultSlowRequest + slowSQL = defaultSlowSQL +) + +// ConfigFromEnv 读取日志环境变量;非法取值直接报错,避免线上悄悄退回到噪声更大的配置。 +func ConfigFromEnv() (Config, error) { + config := Config{Level: slog.LevelInfo, SlowRequest: defaultSlowRequest, SlowSQL: defaultSlowSQL} + if raw := strings.TrimSpace(os.Getenv(EnvLevel)); raw != "" { + parsed, err := ParseLevel(raw) + if err != nil { + return Config{}, err + } + config.Level = parsed + } + switch strings.ToLower(strings.TrimSpace(os.Getenv(EnvFormat))) { + case "", "text": + case "json": + config.JSON = true + default: + return Config{}, fmt.Errorf("%s 只能是 text 或 json", EnvFormat) + } + var err error + if config.SlowRequest, err = envThreshold(EnvSlowRequest, defaultSlowRequest); err != nil { + return Config{}, err + } + if config.SlowSQL, err = envThreshold(EnvSlowSQL, defaultSlowSQL); err != nil { + return Config{}, err + } + return config, nil +} + +func ParseLevel(raw string) (slog.Level, error) { + switch strings.ToLower(strings.TrimSpace(raw)) { + case "debug": + return slog.LevelDebug, nil + case "info": + return slog.LevelInfo, nil + case "warn", "warning": + return slog.LevelWarn, nil + case "error": + return slog.LevelError, nil + default: + return 0, fmt.Errorf("%s 只能是 debug、info、warn 或 error", EnvLevel) + } +} + +func envThreshold(key string, fallback time.Duration) (time.Duration, error) { + raw := strings.TrimSpace(os.Getenv(key)) + if raw == "" { + return fallback, nil + } + if raw == "0" { + return 0, nil + } + parsed, err := time.ParseDuration(raw) + if err != nil || parsed < 0 { + return 0, fmt.Errorf("%s 必须是非负时长,例如 2s;0 表示关闭", key) + } + return parsed, nil +} + +// Setup 安装全局日志 Handler,必须在打开数据库、创建路由之前调用。 +func Setup(config Config) { + output := config.Output + if output == nil { + output = os.Stderr + } + level.Set(config.Level) + settingsMu.Lock() + slowRequest, slowSQL = config.SlowRequest, config.SlowSQL + settingsMu.Unlock() + + options := &slog.HandlerOptions{Level: level} + var handler slog.Handler + if config.JSON { + handler = slog.NewJSONHandler(output, options) + } else { + handler = slog.NewTextHandler(output, options) + } + slog.SetDefault(slog.New(handler)) + // SetDefault 之后标准库 log 也写入同一个 Handler;存量调用基本都是失败分支,按 WARN 输出。 + slog.SetLogLoggerLevel(slog.LevelWarn) +} + +// SetLevel 允许运行时调整级别(例如临时打开 debug 排障)。 +func SetLevel(value slog.Level) { level.Set(value) } + +func DebugEnabled() bool { return level.Level() <= slog.LevelDebug } + +func slowRequestThreshold() time.Duration { + settingsMu.RLock() + defer settingsMu.RUnlock() + return slowRequest +} + +func slowSQLThreshold() time.Duration { + settingsMu.RLock() + defer settingsMu.RUnlock() + return slowSQL +} + +var sampled sync.Map // key -> 上次放行时间 + +// Every 让同一个 key 在 interval 内只放行一次,用于读路径上会随请求重复出现的告警。 +// key 必须来自有限集合(例如模型 ID),不能带请求级别的随机值,否则会无限增长。 +func Every(key string, interval time.Duration) bool { + now := time.Now() + for { + previous, loaded := sampled.LoadOrStore(key, now) + if !loaded { + return true + } + if now.Sub(previous.(time.Time)) < interval { + return false + } + if sampled.CompareAndSwap(key, previous, now) { + return true + } + } +} diff --git a/backend/internal/logging/logging_test.go b/backend/internal/logging/logging_test.go new file mode 100644 index 000000000..4a5b24011 --- /dev/null +++ b/backend/internal/logging/logging_test.go @@ -0,0 +1,134 @@ +package logging + +import ( + "bytes" + "errors" + "log" + "log/slog" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + "time" + + "github.com/gin-gonic/gin" + "gorm.io/gorm" +) + +func setupBuffer(t *testing.T, level slog.Level) *bytes.Buffer { + t.Helper() + previous := slog.Default() + buffer := &bytes.Buffer{} + Setup(Config{Level: level, SlowRequest: time.Second, SlowSQL: 100 * time.Millisecond, Output: buffer}) + t.Cleanup(func() { + slog.SetDefault(previous) + log.SetOutput(os.Stderr) + log.SetFlags(log.LstdFlags) + }) + return buffer +} + +func TestConfigFromEnv(t *testing.T) { + t.Setenv(EnvLevel, "WARN") + t.Setenv(EnvFormat, "json") + t.Setenv(EnvSlowRequest, "0") + t.Setenv(EnvSlowSQL, "250ms") + config, err := ConfigFromEnv() + if err != nil { + t.Fatal(err) + } + if config.Level != slog.LevelWarn || !config.JSON || config.SlowRequest != 0 || config.SlowSQL != 250*time.Millisecond { + t.Fatalf("unexpected config: %+v", config) + } + t.Setenv(EnvLevel, "verbose") + if _, err := ConfigFromEnv(); err == nil { + t.Fatal("invalid level must be rejected") + } +} + +func TestAccessLogSkipsSuccessfulQueries(t *testing.T) { + gin.SetMode(gin.TestMode) + buffer := setupBuffer(t, slog.LevelInfo) + router := gin.New() + router.Use(AccessLog(func(path string) string { return strings.ReplaceAll(path, "secret", ":token") })) + router.GET("/api/items", func(c *gin.Context) { c.Status(http.StatusOK) }) + router.GET("/api/broken", func(c *gin.Context) { c.Status(http.StatusInternalServerError) }) + router.POST("/api/items", func(c *gin.Context) { c.Status(http.StatusCreated) }) + router.POST("/api/runs/:id/heartbeat", func(c *gin.Context) { c.Status(http.StatusOK) }) + router.GET("/api/share/:token", func(c *gin.Context) { c.Status(http.StatusNotFound) }) + + serve := func(method, path string) { + router.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest(method, path, nil)) + } + serve(http.MethodGet, "/api/items") + serve(http.MethodPost, "/api/runs/r1/heartbeat") + if buffer.Len() != 0 { + t.Fatalf("successful queries must not be logged at info level: %s", buffer.String()) + } + serve(http.MethodPost, "/api/items") + serve(http.MethodGet, "/api/broken") + serve(http.MethodGet, "/api/share/secret") + output := buffer.String() + for _, want := range []string{"level=INFO", "status=201", "level=ERROR", "status=500", "level=WARN", "path=/api/share/:token"} { + if !strings.Contains(output, want) { + t.Fatalf("missing %q in %s", want, output) + } + } + if strings.Contains(output, "secret") { + t.Fatalf("redacted path leaked: %s", output) + } +} + +func TestAccessLevelSlowRequest(t *testing.T) { + setupBuffer(t, slog.LevelInfo) + if got := accessLevel(http.MethodGet, "/api/items", 200, 2*time.Second, false); got != slog.LevelWarn { + t.Fatalf("slow query should warn, got %v", got) + } + if got := accessLevel(http.MethodGet, "/api/agent/runs/:id/events", 200, time.Hour, true); got != slog.LevelDebug { + t.Fatalf("long-lived streams are not slow requests, got %v", got) + } +} + +func TestStdlogBridgesToWarn(t *testing.T) { + buffer := setupBuffer(t, slog.LevelWarn) + log.Printf("legacy failure: %v", errors.New("boom")) + if !strings.Contains(buffer.String(), "level=WARN") || !strings.Contains(buffer.String(), "legacy failure: boom") { + t.Fatalf("std log should reach the unified handler as WARN: %s", buffer.String()) + } + slog.Info("info line") + if strings.Contains(buffer.String(), "info line") { + t.Fatal("info must be filtered at warn level") + } +} + +func TestGormLoggerOnlyLogsFailuresAndSlowQueries(t *testing.T) { + buffer := setupBuffer(t, slog.LevelInfo) + logger := GormLogger() + sql := func() (string, int64) { return "SELECT * FROM users WHERE id = $1", 1 } + logger.Trace(t.Context(), time.Now(), sql, nil) + logger.Trace(t.Context(), time.Now(), sql, gorm.ErrRecordNotFound) + if buffer.Len() != 0 { + t.Fatalf("successful or not-found queries must not be logged: %s", buffer.String()) + } + logger.Trace(t.Context(), time.Now().Add(-time.Second), sql, nil) + logger.Trace(t.Context(), time.Now(), sql, errors.New("deadlock")) + output := buffer.String() + if !strings.Contains(output, `msg="sql slow"`) || !strings.Contains(output, `msg="sql failed"`) || !strings.Contains(output, "deadlock") { + t.Fatalf("slow and failed SQL must be logged: %s", output) + } + filter, ok := logger.(gorm.ParamsFilter) + if !ok { + t.Fatal("GORM logger must implement ParamsFilter so SQL parameters stay out of logs") + } + if _, vars := filter.ParamsFilter(t.Context(), "SELECT 1", "secret"); vars != nil { + t.Fatal("SQL parameters must be dropped from logs") + } +} + +func TestEvery(t *testing.T) { + key := "test-every-" + time.Now().String() + if !Every(key, time.Hour) || Every(key, time.Hour) { + t.Fatal("Every should allow the first call and suppress repeats within the interval") + } +} diff --git a/docker-compose.deploy.yml b/docker-compose.deploy.yml index 5e76324a7..3daac69c5 100644 --- a/docker-compose.deploy.yml +++ b/docker-compose.deploy.yml @@ -74,6 +74,8 @@ services: YINGCE_AGENT_URL: http://yingce-agent:8081 YINGCE_AGENT_TOKEN: ${YINGCE_AGENT_TOKEN:?请先配置 YINGCE_AGENT_TOKEN} YINGCE_AGENT_BRIDGE_HOST: backend + CANVAS_LOG_LEVEL: ${CANVAS_LOG_LEVEL:-info} + CANVAS_LOG_FORMAT: ${CANVAS_LOG_FORMAT:-text} GIN_MODE: release volumes: - ${CANVAS_DATA_PATH:-backend-data}:/data diff --git a/docker-compose.dev.yml b/docker-compose.dev.yml index fcf16dc56..f488a3fa6 100644 --- a/docker-compose.dev.yml +++ b/docker-compose.dev.yml @@ -28,6 +28,7 @@ services: CANVAS_CORS_ORIGINS: ${CANVAS_CORS_ORIGINS:-http://localhost:3000} # 服务器访问地址:Agent 看图与生成参考图都靠它签发上游可取到的短时链接。 CANVAS_PUBLIC_BASE_URL: ${CANVAS_PUBLIC_BASE_URL:-} + CANVAS_LOG_LEVEL: ${CANVAS_LOG_LEVEL:-debug} GIN_MODE: debug volumes: - type: bind diff --git a/docker-compose.local.yml b/docker-compose.local.yml index a95c20666..ee1a7584c 100644 --- a/docker-compose.local.yml +++ b/docker-compose.local.yml @@ -22,6 +22,8 @@ services: # 服务器访问地址:Agent 看图与生成参考图都靠它签发上游可取到的短时链接。 CANVAS_PUBLIC_BASE_URL: ${CANVAS_PUBLIC_BASE_URL:-} ENABLE_PROVIDER_PLUGINS: ${ENABLE_PROVIDER_PLUGINS:-false} + CANVAS_LOG_LEVEL: ${CANVAS_LOG_LEVEL:-info} + CANVAS_LOG_FORMAT: ${CANVAS_LOG_FORMAT:-text} GIN_MODE: release volumes: - backend-data:/data diff --git a/docker-compose.server.yml b/docker-compose.server.yml index c4c19ec7b..ec2b974e5 100644 --- a/docker-compose.server.yml +++ b/docker-compose.server.yml @@ -69,6 +69,8 @@ services: CANVAS_ALLOWED_PRIVATE_UPSTREAM_HOSTS: ${CANVAS_ALLOWED_PRIVATE_UPSTREAM_HOSTS:-} CANVAS_CORS_ORIGINS: ${CANVAS_CORS_ORIGINS:-*} CANVAS_PUBLIC_BASE_URL: ${CANVAS_PUBLIC_BASE_URL:-} + CANVAS_LOG_LEVEL: ${CANVAS_LOG_LEVEL:-info} + CANVAS_LOG_FORMAT: ${CANVAS_LOG_FORMAT:-text} GIN_MODE: release volumes: - ${CANVAS_DATA_PATH:-./data}:/data diff --git a/docker-compose.yml b/docker-compose.yml index 763cc847a..e8a6ae3d8 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -21,6 +21,8 @@ services: CANVAS_CORS_ORIGINS: ${CANVAS_CORS_ORIGINS:-http://localhost:3000} # 服务器访问地址:Agent 看图与生成参考图都靠它签发上游可取到的短时链接。 CANVAS_PUBLIC_BASE_URL: ${CANVAS_PUBLIC_BASE_URL:-} + CANVAS_LOG_LEVEL: ${CANVAS_LOG_LEVEL:-info} + CANVAS_LOG_FORMAT: ${CANVAS_LOG_FORMAT:-text} GIN_MODE: release volumes: - backend-data:/data diff --git a/docs/content/docs/progress/pending-test.mdx b/docs/content/docs/progress/pending-test.mdx index 355cc9286..dc947fab3 100644 --- a/docs/content/docs/progress/pending-test.mdx +++ b/docs/content/docs/progress/pending-test.mdx @@ -5,6 +5,13 @@ description: 当前项目已实现功能的手工验证清单与未确认边界 # 待测试 +## 后端统一日志与降噪 + +- 已实现:新增 `backend/internal/logging`,统一接管 slog、标准库 `log`、GORM 与 Gin 访问日志,级别与格式由 `CANVAS_LOG_LEVEL` / `CANVAS_LOG_FORMAT` 控制。`info` 下不再输出成功的查询类请求、成功 SQL、`[Agent] message_end` 等流式事件及常规画布自动保存;4xx/5xx、慢请求、慢 SQL、SQL 失败和 panic 仍会记录,SQL 不带参数值。 +- [x] `go build ./...`、`go test ./...` 与 `internal/logging` 单元测试通过。 +- [ ] 部署到服务器后观察一段时间的日志量,确认没有遗漏的高频输出;临时切换 `CANVAS_LOG_LEVEL=debug` 验证 Agent 事件与查询请求可以重新看到,再切回 `info`。 +- [ ] 若接入日志采集,验证 `CANVAS_LOG_FORMAT=json` 的字段(`request_id`、`status`、`latency_ms`)可被正确解析。 + ## 模型选择弹窗长描述与视口边界 - 已调整:共用 `ModelPicker` 的宽度由共享样式统一控制,移除按内容撑宽及触发器最小宽度约束;渠道描述支持换行,字号统一使用说明文字 token(12px),行高为 1.5,移除旧 9px / 10px 覆盖;模型名称与价格在空间不足时分行显示,长价格文本可换行。