feat(platform): 日志管理 - 统一日志出口并屏蔽查询与 Agent 流式事件日志

新增 internal/logging,slog、标准库 log、GORM 与 Gin 访问日志共用同一 Handler,由 CANVAS_LOG_LEVEL / CANVAS_LOG_FORMAT 控制。info 级别不再输出成功的查询类请求、成功 SQL、message_end 等 Agent 流式事件和常规画布自动保存;4xx/5xx、慢请求、慢 SQL、SQL 失败与 panic 仍会记录,SQL 不内联参数值。
This commit is contained in:
ddcat666
2026-09-30 03:33:34 +08:00
parent 42e2433b4a
commit b59317415d
21 changed files with 602 additions and 44 deletions

View File

@@ -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

View File

@@ -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
}

View File

@@ -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 尚未结束")
}

View File

@@ -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)

View File

@@ -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
}

View File

@@ -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

View File

@@ -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
}

View File

@@ -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)

View File

@@ -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)
}
}

View File

@@ -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)
}

View File

@@ -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)

View File

@@ -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)"
}

View File

@@ -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)
})
}

View File

@@ -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
}
}
}

View File

@@ -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")
}
}

View File

@@ -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

View File

@@ -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

View File

@@ -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

View File

@@ -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

View File

@@ -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

View File

@@ -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 覆盖;模型名称与价格在空间不足时分行显示,长价格文本可换行。