WeKnora deployment source with the reviewed wiki identity, summary and recovery fixes

internal/logger/accesspolicy_context_test.go

@@ -0,0 +1,52 @@
+package logger
+
+import (
+	"context"
+	"testing"
+
+	"github.com/Tencent/WeKnora/internal/accesspolicy"
+)
+
+func TestClonedContextPreservesResourceAuthorization(t *testing.T) {
+	for name, clone := range map[string]func(context.Context) context.Context{
+		"with_trace":    CloneContext,
+		"without_trace": CloneContextWithoutTrace,
+	} {
+		t.Run(name, func(t *testing.T) {
+			ctx, cancel := context.WithCancel(context.Background())
+			ctx = accesspolicy.WithSnapshot(ctx, &accesspolicy.Snapshot{
+				Restricted:   true,
+				Permissions:  map[string]bool{"knowledge.read": true},
+				Publications: map[string]bool{"knowledge:published": true},
+				Grants:       map[string]bool{"knowledge:granted": true},
+				Hidden:       map[string]bool{"knowledge:hidden": true},
+				NoExport:     map[string]bool{"knowledge:published": true},
+			})
+			cancel()
+			detached := clone(ctx)
+			if detached.Err() != nil {
+				t.Fatal("cloned work must remain detached from request cancellation")
+			}
+			policy := accesspolicy.FromContext(detached)
+			if policy == nil || !policy.Restricted {
+				t.Fatal("authenticated resource restrictions must survive context cloning")
+			}
+			if !accesspolicy.Allowed(detached, "knowledge.read") || accesspolicy.Allowed(detached, "knowledge.write") {
+				t.Fatal("cloning changed module permissions")
+			}
+			if accesspolicy.Readable(detached, "knowledge", "private", false, policy == nil) {
+				t.Fatal("cloning must not expose another user's private knowledge")
+			}
+			if !accesspolicy.Readable(detached, "knowledge", "granted", false, false) ||
+				!accesspolicy.Readable(detached, "knowledge", "published", false, false) {
+				t.Fatal("cloning must retain explicit grants and publications")
+			}
+			if accesspolicy.Readable(detached, "knowledge", "hidden", true, true) || !policy.NoExport["knowledge:published"] {
+				t.Fatal("cloning must retain hidden-resource and export restrictions")
+			}
+			if accesspolicy.FromContext(clone(context.Background())) != nil {
+				t.Fatal("background workers without a snapshot retain native behavior")
+			}
+		})
+	}
+}

internal/logger/llm_logger.go

@@ -0,0 +1,247 @@
+package logger
+
+import (
+	"context"
+	"fmt"
+	"os"
+	"path/filepath"
+	"strings"
+	"sync"
+	"time"
+)
+
+var llmDebug struct {
+	mu      sync.Mutex
+	enabled bool
+	dir     string
+}
+
+func init() {
+	configureLLMDebugLog()
+}
+
+func configureLLMDebugLog() {
+	val := strings.TrimSpace(os.Getenv("LLM_DEBUG_LOG"))
+	if val == "" || val == "false" || val == "0" {
+		return
+	}
+
+	var dir string
+	if val == "true" || val == "1" {
+		dir = resolveLLMDebugDir()
+	} else {
+		dir = val
+	}
+	if dir == "" {
+		dir = "llm_debug"
+	}
+
+	if err := os.MkdirAll(dir, 0o755); err != nil {
+		fmt.Fprintf(os.Stderr, "llm_debug: failed to create dir %s: %v\n", dir, err)
+		return
+	}
+
+	llmDebug.dir = dir
+	llmDebug.enabled = true
+
+	go cleanupOldDebugFiles(dir, 7*24*time.Hour)
+
+	fmt.Fprintf(os.Stderr, "llm_debug: LLM debug log enabled → %s/\n", dir)
+}
+
+func resolveLLMDebugDir() string {
+	if logPath := strings.TrimSpace(os.Getenv("LOG_PATH")); logPath != "" {
+		return filepath.Join(filepath.Dir(logPath), "llm_debug")
+	}
+	if macPath := defaultMacAppLogPath(); macPath != "" {
+		return filepath.Join(filepath.Dir(macPath), "llm_debug")
+	}
+	return "llm_debug"
+}
+
+// cleanupOldDebugFiles removes files older than maxAge from the debug directory.
+func cleanupOldDebugFiles(dir string, maxAge time.Duration) {
+	entries, err := os.ReadDir(dir)
+	if err != nil {
+		return
+	}
+	cutoff := time.Now().Add(-maxAge)
+	for _, e := range entries {
+		if e.IsDir() {
+			continue
+		}
+		info, err := e.Info()
+		if err != nil {
+			continue
+		}
+		if info.ModTime().Before(cutoff) {
+			_ = os.Remove(filepath.Join(dir, e.Name()))
+		}
+	}
+}
+
+// LLMDebugEnabled returns true when the dedicated LLM debug log is active.
+func LLMDebugEnabled() bool {
+	return llmDebug.enabled
+}
+
+// LLMDebugLog writes a complete model call record to a per-request log file.
+// All calls sharing the same request_id are appended to the same file.
+func LLMDebugLog(ctx context.Context, record *LLMCallRecord) {
+	if !llmDebug.enabled || record == nil {
+		return
+	}
+
+	text := formatRecord(record)
+
+	reqID := extractRequestID(ctx)
+	filename := buildFilename(reqID)
+
+	llmDebug.mu.Lock()
+	defer llmDebug.mu.Unlock()
+
+	path := filepath.Join(llmDebug.dir, filename)
+	f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o644)
+	if err != nil {
+		fmt.Fprintf(os.Stderr, "llm_debug: open %s: %v\n", path, err)
+		return
+	}
+	defer f.Close()
+	_, _ = f.WriteString(text)
+}
+
+func buildFilename(reqID string) string {
+	if reqID != "" {
+		return reqID + ".log"
+	}
+	return time.Now().Format("20060102_150405.000") + ".log"
+}
+
+func formatRecord(r *LLMCallRecord) string {
+	var b strings.Builder
+	b.Grow(4096)
+
+	separator := fmt.Sprintf("================ %s ================", r.CallType)
+	b.WriteString("\n")
+	b.WriteString(separator)
+	b.WriteString("\n")
+	b.WriteString(fmt.Sprintf("Time:     %s\n", time.Now().Format("2006-01-02 15:04:05.000")))
+	b.WriteString(fmt.Sprintf("Model:    %s\n", r.Model))
+	if r.Duration > 0 {
+		b.WriteString(fmt.Sprintf("Duration: %s\n", r.Duration.Round(time.Millisecond)))
+	}
+
+	for _, s := range r.Sections {
+		b.WriteString(fmt.Sprintf("\n---------- %s ----------\n", s.Title))
+		b.WriteString(s.Content)
+		if !strings.HasSuffix(s.Content, "\n") {
+			b.WriteString("\n")
+		}
+	}
+
+	if r.Error != "" {
+		b.WriteString("\n---------- Error ----------\n")
+		b.WriteString(r.Error)
+		b.WriteString("\n")
+	}
+
+	b.WriteString(strings.Repeat("=", len(separator)))
+	b.WriteString("\n")
+
+	return b.String()
+}
+
+func extractRequestID(ctx context.Context) string {
+	entry := GetLogger(ctx)
+	if v, ok := entry.Data["request_id"]; ok {
+		return fmt.Sprintf("%v", v)
+	}
+	return ""
+}
+
+// ---------- Record types ----------
+
+// LLMCallRecord holds all information for one model API call.
+type LLMCallRecord struct {
+	CallType string // "Chat", "Chat Stream", "Embedding", "Rerank", "VLM"
+	Model    string
+	Duration time.Duration
+	Sections []RecordSection
+	Error    string
+}
+
+// RecordSection is a titled block of text within a call record.
+type RecordSection struct {
+	Title   string
+	Content string
+}
+
+// ---------- Shared helpers for building sections ----------
+
+// LLMMessage is a simplified chat message for logging.
+type LLMMessage struct {
+	Role       string
+	Content    string
+	Name       string
+	ToolCallID string
+	Images     []string
+	ToolCalls  []LLMToolCallInfo
+}
+
+// LLMToolCallInfo holds tool call info for logging.
+type LLMToolCallInfo struct {
+	ID        string
+	FuncName  string
+	Arguments string
+}
+
+// FormatMessages formats chat messages into a readable block.
+func FormatMessages(messages []LLMMessage) string {
+	var b strings.Builder
+	for _, m := range messages {
+		b.WriteString(fmt.Sprintf("[%s]", m.Role))
+		if m.Name != "" {
+			b.WriteString(fmt.Sprintf(" name=%s", m.Name))
+		}
+		if m.ToolCallID != "" {
+			b.WriteString(fmt.Sprintf(" tool_call_id=%s", m.ToolCallID))
+		}
+		b.WriteString("\n")
+
+		if m.Content != "" {
+			b.WriteString(m.Content)
+			b.WriteString("\n")
+		}
+		for _, img := range m.Images {
+			if len([]rune(img)) > 80 {
+				b.WriteString(fmt.Sprintf("[image: %s (%d bytes)]\n", TruncateRunes(img, 80), len(img)))
+			} else {
+				b.WriteString(fmt.Sprintf("[image: %s]\n", img))
+			}
+		}
+		for _, tc := range m.ToolCalls {
+			b.WriteString(fmt.Sprintf("  -> tool_call: id=%s, func=%s, args=%s\n", tc.ID, tc.FuncName, tc.Arguments))
+		}
+		b.WriteString("\n")
+	}
+	return b.String()
+}
+
+// FormatToolCalls formats response tool calls into a readable block.
+func FormatToolCalls(tcs []LLMToolCallInfo) string {
+	var b strings.Builder
+	for _, tc := range tcs {
+		b.WriteString(fmt.Sprintf("[tool_call] id=%s, func=%s\n%s\n\n", tc.ID, tc.FuncName, tc.Arguments))
+	}
+	return b.String()
+}
+
+// TruncateRunes truncates a string to maxRunes runes, appending "..." if truncated.
+// This is safe for multi-byte UTF-8 characters (e.g. Chinese).
+func TruncateRunes(s string, maxRunes int) string {
+	runes := []rune(s)
+	if len(runes) <= maxRunes {
+		return s
+	}
+	return string(runes[:maxRunes]) + "..."
+}

internal/logger/logger.go

@@ -0,0 +1,549 @@
+package logger
+
+import (
+	"context"
+	"fmt"
+	"io"
+	"os"
+	"path"
+	"path/filepath"
+	"regexp"
+	"runtime"
+	"sort"
+	"strings"
+	"sync"
+
+	"github.com/Tencent/WeKnora/internal/types"
+	"github.com/sirupsen/logrus"
+	"go.opentelemetry.io/otel/trace"
+	"gopkg.in/natefinch/lumberjack.v2"
+)
+
+// appLogger 使用私有实例，避免外部依赖改写 logrus 全局状态导致日志丢失
+var appLogger = logrus.New()
+
+var (
+	loggerMu      sync.Mutex
+	activeLogFile io.WriteCloser
+	ansiEscapeRE  = regexp.MustCompile(`\x1b\[[0-9;]*[a-zA-Z]`)
+)
+
+// ansiStripWriter removes ANSI color/style sequences so file logs stay plain text
+// while stdout can still render colors in a terminal.
+type ansiStripWriter struct {
+	w io.Writer
+}
+
+func (s *ansiStripWriter) Write(p []byte) (int, error) {
+	_, err := s.w.Write(ansiEscapeRE.ReplaceAll(p, nil))
+	return len(p), err
+}
+
+// LogLevel 日志级别类型
+type LogLevel string
+
+// 日志级别常量
+const (
+	LevelDebug LogLevel = "debug"
+	LevelInfo  LogLevel = "info"
+	LevelWarn  LogLevel = "warn"
+	LevelError LogLevel = "error"
+	LevelFatal LogLevel = "fatal"
+)
+
+// ANSI颜色代码
+const (
+	colorRed    = "\033[31m"
+	colorGreen  = "\033[32m"
+	colorYellow = "\033[33m"
+	colorBlue   = "\033[34m"
+	colorPurple = "\033[35m"
+	colorCyan   = "\033[36m"
+	colorWhite  = "\033[37m"
+	colorGray   = "\033[90m"
+	colorBold   = "\033[1m"
+	colorReset  = "\033[0m"
+)
+
+type CustomFormatter struct {
+	ForceColor bool   // 是否强制使用颜色，即使在非终端环境下
+	Template   string // 自定义日志格式模板，通过 LOG_FORMAT 环境变量配置，为空则使用内置默认格式
+	// 模板占位符：%d=时间 %level=级别 %thread=goroutine %logger=caller %traceId=请求ID %msg=消息+结构化字段
+
+	// threadNeeded 缓存模板是否引用了 %thread，避免每条日志都调用一次 runtime.Stack。
+	threadNeeded bool
+}
+
+// levelColorFor 返回日志级别对应的 ANSI 颜色码，无颜色时返回空串。
+func levelColorFor(level logrus.Level) string {
+	switch level {
+	case logrus.DebugLevel:
+		return colorCyan
+	case logrus.InfoLevel:
+		return colorGreen
+	case logrus.WarnLevel:
+		return colorYellow
+	case logrus.ErrorLevel:
+		return colorRed
+	case logrus.FatalLevel:
+		return colorPurple
+	}
+	return ""
+}
+
+func (f *CustomFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	timestamp := entry.Time.Format("2006-01-02 15:04:05.000")
+	level := strings.ToUpper(entry.Level.String())
+
+	// 提取已知字段
+	caller, _ := entry.Data["caller"].(string)
+	traceID, _ := entry.Data["request_id"].(string)
+
+	// 剩余结构化字段
+	keys := make([]string, 0, len(entry.Data))
+	for k := range entry.Data {
+		if k != "caller" && k != "request_id" {
+			keys = append(keys, k)
+		}
+	}
+	sort.Strings(keys)
+
+	// 自定义模板模式
+	if f.Template != "" {
+		msg := entry.Message
+		for _, k := range keys {
+			msg += fmt.Sprintf(" %s=%v", k, entry.Data[k])
+		}
+		shortCaller := caller
+		if len(shortCaller) > 50 {
+			shortCaller = shortCaller[len(shortCaller)-50:]
+		}
+		// 仅在模板引用 %thread 时才取 goroutine ID，避免每条日志都执行 runtime.Stack
+		thread := ""
+		if f.threadNeeded {
+			thread = getGoroutineID()
+		}
+		// 级别染色在占位符替换阶段完成，避免后续在整行做 ReplaceAll
+		// 误染消息内容里出现的 "INFO"/"ERROR" 等字面字符串。
+		levelOut := level
+		if f.ForceColor {
+			if c := levelColorFor(entry.Level); c != "" {
+				levelOut = c + level + colorReset
+			}
+		}
+		// 使用 NewReplacer 做单趟替换，避免链式 ReplaceAll 时
+		// 前一个占位符的值里恰好包含后续占位符字面串导致的二次替换。
+		r := strings.NewReplacer(
+			"%d", timestamp,
+			"%level", levelOut,
+			"%thread", thread,
+			"%logger", shortCaller,
+			"%traceId", traceID,
+			"%msg", msg,
+		)
+		return []byte(r.Replace(f.Template) + "\n"), nil
+	}
+
+	// 默认格式（保持原有行为）
+	var levelColor, resetColor string
+	if f.ForceColor {
+		switch entry.Level {
+		case logrus.DebugLevel:
+			levelColor = colorCyan
+		case logrus.InfoLevel:
+			levelColor = colorGreen
+		case logrus.WarnLevel:
+			levelColor = colorYellow
+		case logrus.ErrorLevel:
+			levelColor = colorRed
+		case logrus.FatalLevel:
+			levelColor = colorPurple
+		default:
+			levelColor = colorReset
+		}
+		resetColor = colorReset
+	}
+
+	fields := ""
+
+	// request_id 优先输出
+	if v, ok := entry.Data["request_id"]; ok {
+		if f.ForceColor {
+			fields += fmt.Sprintf("%s%v%s ",
+				colorBlue, v, colorReset)
+		} else {
+			fields += fmt.Sprintf("%v ", v)
+		}
+	}
+
+	// 其余字段排序后输出
+	for _, k := range keys {
+		if f.ForceColor {
+			val := fmt.Sprintf("%v", entry.Data[k])
+			coloredVal := fmt.Sprintf("%s%s%s", colorWhite, val, colorReset)
+			if k == "error" {
+				coloredVal = fmt.Sprintf("%s%s%s", colorRed, val, colorReset)
+			}
+			fields += fmt.Sprintf("%s%s%s=%s ",
+				colorCyan, k, colorReset, coloredVal)
+		} else {
+			fields += fmt.Sprintf("%s=%v ", k, entry.Data[k])
+		}
+	}
+
+	fields = strings.TrimSpace(fields)
+
+	// 拼接最终输出内容，添加颜色
+	if f.ForceColor {
+		coloredTimestamp := fmt.Sprintf("%s%s%s", colorGray, timestamp, resetColor)
+		coloredCaller := caller
+		if caller != "" {
+			coloredCaller = fmt.Sprintf("%s%s%s", colorPurple, caller, resetColor)
+		}
+		return []byte(fmt.Sprintf("%s%-5s%s[%s] [%s] %-20s | %s\n",
+			levelColor, level, resetColor, coloredTimestamp, fields, coloredCaller, entry.Message)), nil
+	}
+
+	return []byte(fmt.Sprintf("%-5s[%s] [%s] %-20s | %s\n",
+		level, timestamp, fields, caller, entry.Message)), nil
+}
+
+func getGoroutineID() string {
+	buf := make([]byte, 64)
+	buf = buf[:runtime.Stack(buf, false)]
+	// buf 格式: "goroutine 123 [running]:\n..."
+	i := 0
+	for i < len(buf) && buf[i] != ' ' {
+		i++
+	}
+	if i >= len(buf) {
+		return "0"
+	}
+	buf = buf[i+1:]
+	j := 0
+	for j < len(buf) && buf[j] != ' ' {
+		j++
+	}
+	return string(buf[:j])
+}
+
+// 初始化全局日志设置
+func init() {
+	ConfigureFromEnv()
+}
+
+// ConfigureFromEnv 重新从环境变量应用日志配置。
+// 这允许在 main() 中加载 .env 后，让 LOG_LEVEL / LOG_PATH 立即生效。
+func ConfigureFromEnv() {
+	loggerMu.Lock()
+	defer loggerMu.Unlock()
+
+	if activeLogFile != nil {
+		_ = activeLogFile.Close()
+		activeLogFile = nil
+	}
+
+	// 根据环境变量设置全局日志级别
+	logLevel := getLogLevelFromEnv()
+	appLogger.SetLevel(logLevel)
+
+	writer := io.Writer(os.Stdout)
+	logPath := resolveLogPathFromEnv()
+	if logPath != "" {
+		file, err := openLogFile(logPath)
+		if err != nil {
+			fmt.Fprintf(os.Stderr, "logger: failed to open log file %s: %v\n", logPath, err)
+		} else {
+			activeLogFile = file
+			writer = io.MultiWriter(os.Stdout, &ansiStripWriter{w: file})
+		}
+	}
+
+	// 默认继续输出到 stdout，同时在可用时落盘到文件
+	appLogger.SetOutput(writer)
+
+	// 非终端（如 Docker 日志采集）禁用 ANSI 颜色，避免日志聚合/检索异常
+	forceColor := false
+	if fi, err := os.Stdout.Stat(); err == nil {
+		forceColor = (fi.Mode() & os.ModeCharDevice) != 0
+	}
+
+	// 设置日志格式而不修改全局时区
+	tmpl := resolveLogFormatFromEnv()
+	appLogger.SetFormatter(&CustomFormatter{
+		ForceColor:   forceColor,
+		Template:     tmpl,
+		threadNeeded: strings.Contains(tmpl, "%thread"),
+	})
+	appLogger.SetReportCaller(false)
+}
+
+// GetLogger 获取日志实例
+func GetLogger(c context.Context) *logrus.Entry {
+	if logger := c.Value(types.LoggerContextKey); logger != nil {
+		return logger.(*logrus.Entry)
+	}
+	return logrus.NewEntry(appLogger)
+}
+
+// SetOutput overrides the internal logger's output destination.
+// Intended for use in tests that need to capture and assert on log content
+// (e.g. verifying secrets are not written out). Restore the original writer
+// (usually os.Stdout) in a defer after the test.
+func SetOutput(w io.Writer) {
+	loggerMu.Lock()
+	defer loggerMu.Unlock()
+	appLogger.SetOutput(w)
+}
+
+// SetLogLevel 设置日志级别
+func SetLogLevel(level LogLevel) {
+	var logLevel logrus.Level
+
+	switch level {
+	case LevelDebug:
+		logLevel = logrus.DebugLevel
+	case LevelInfo:
+		logLevel = logrus.InfoLevel
+	case LevelWarn:
+		logLevel = logrus.WarnLevel
+	case LevelError:
+		logLevel = logrus.ErrorLevel
+	case LevelFatal:
+		logLevel = logrus.FatalLevel
+	default:
+		logLevel = logrus.InfoLevel
+	}
+
+	appLogger.SetLevel(logLevel)
+}
+
+// getLogLevelFromEnv 从环境变量读取日志级别配置
+func getLogLevelFromEnv() logrus.Level {
+	// 从环境变量读取LOG_LEVEL配置
+	logLevelStr := strings.ToLower(os.Getenv("LOG_LEVEL"))
+
+	switch logLevelStr {
+	case "debug":
+		return logrus.DebugLevel
+	case "info":
+		return logrus.InfoLevel
+	case "warn", "warning":
+		return logrus.WarnLevel
+	case "error":
+		return logrus.ErrorLevel
+	case "fatal":
+		return logrus.FatalLevel
+	default:
+		return logrus.DebugLevel // 无效配置时使用默认值
+	}
+}
+
+func resolveLogPathFromEnv() string {
+	if logPath := strings.TrimSpace(os.Getenv("LOG_PATH")); logPath != "" {
+		return filepath.Clean(logPath)
+	}
+	return defaultMacAppLogPath()
+}
+
+// resolveLogFormatFromEnv 从环境变量 LOG_FORMAT 读取自定义日志格式模板。
+// 为空则使用内置默认格式；非空则作为模板，支持占位符：
+// %d=时间 %level=级别 %thread=goroutine %logger=caller %traceId=请求ID %msg=消息+结构化字段
+func resolveLogFormatFromEnv() string {
+	return strings.TrimSpace(os.Getenv("LOG_FORMAT"))
+}
+
+func defaultMacAppLogPath() string {
+	execPath, err := os.Executable()
+	if err != nil || !strings.Contains(execPath, ".app/Contents/MacOS") {
+		return ""
+	}
+
+	homeDir, err := os.UserHomeDir()
+	if err != nil {
+		return ""
+	}
+
+	appName := "WeKnora Lite"
+	if idx := strings.Index(execPath, ".app/Contents/MacOS"); idx >= 0 {
+		bundleName := filepath.Base(execPath[:idx+4])
+		if trimmed := strings.TrimSuffix(bundleName, ".app"); trimmed != "" {
+			appName = trimmed
+		}
+	}
+
+	return filepath.Join(homeDir, "Library", "Logs", appName, appName+".log")
+}
+
+func openLogFile(logPath string) (io.WriteCloser, error) {
+	dir := filepath.Dir(logPath)
+	if dir != "." {
+		if err := os.MkdirAll(dir, 0o755); err != nil {
+			return nil, err
+		}
+	}
+	return &lumberjack.Logger{
+		Filename:   logPath,
+		MaxSize:    50, // megabytes
+		MaxBackups: 3,
+		MaxAge:     28, // days
+		Compress:   true,
+	}, nil
+}
+
+// 添加调用者字段
+func addCaller(entry *logrus.Entry, skip int) *logrus.Entry {
+	pc, file, line, ok := runtime.Caller(skip)
+	if !ok {
+		return entry
+	}
+	shortFile := path.Base(file)
+	funcName := "unknown"
+	if fn := runtime.FuncForPC(pc); fn != nil {
+		// 只保留函数名，不带包路径（如 doSomething）
+		fullName := path.Base(fn.Name())
+		parts := strings.Split(fullName, ".")
+		funcName = parts[len(parts)-1]
+	}
+	return entry.WithField("caller", fmt.Sprintf("%s:%d[%s]", shortFile, line, funcName))
+}
+
+// WithRequestID 在日志中添加请求ID
+func WithRequestID(c context.Context, requestID string) context.Context {
+	return WithField(c, "request_id", requestID)
+}
+
+// WithField 向日志中添加一个字段
+func WithField(c context.Context, key string, value interface{}) context.Context {
+	logger := GetLogger(c).WithField(key, value)
+	return context.WithValue(c, types.LoggerContextKey, logger)
+}
+
+// WithFields 向日志中添加多个字段
+func WithFields(c context.Context, fields logrus.Fields) context.Context {
+	logger := GetLogger(c).WithFields(fields)
+	return context.WithValue(c, types.LoggerContextKey, logger)
+}
+
+// Debug 输出调试级别的日志
+func Debug(c context.Context, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Debug(args...)
+}
+
+// Debugf 使用格式化字符串输出调试级别的日志
+func Debugf(c context.Context, format string, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Debugf(format, args...)
+}
+
+// Info 输出信息级别的日志
+func Info(c context.Context, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Info(args...)
+}
+
+// Infof 使用格式化字符串输出信息级别的日志
+func Infof(c context.Context, format string, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Infof(format, args...)
+}
+
+// Warn 输出警告级别的日志
+func Warn(c context.Context, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Warn(args...)
+}
+
+// Warnf 使用格式化字符串输出警告级别的日志
+func Warnf(c context.Context, format string, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Warnf(format, args...)
+}
+
+// Fields aliases logrus.Fields so callers in other packages can use the
+// short form `logger.Fields{...}` without importing logrus directly.
+type Fields = logrus.Fields
+
+// WarnWithFields emits a warning with structured fields. Use this for
+// audit-relevant events (cross-tenant probes, invariant violations) so that
+// log aggregators can index the tenant/resource identifiers without
+// parsing free-form text. Format-string style (Warnf) is appropriate for
+// low-stakes diagnostic messages.
+func WarnWithFields(c context.Context, fields Fields, msg string) {
+	if fields == nil {
+		fields = Fields{}
+	}
+	addCaller(GetLogger(c), 2).WithFields(fields).Warn(msg)
+}
+
+// Error 输出错误级别的日志
+func Error(c context.Context, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Error(args...)
+}
+
+// Errorf 使用格式化字符串输出错误级别的日志
+func Errorf(c context.Context, format string, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Errorf(format, args...)
+}
+
+// ErrorWithFields 输出带有额外字段的错误级别日志
+func ErrorWithFields(c context.Context, err error, fields logrus.Fields) {
+	if fields == nil {
+		fields = logrus.Fields{}
+	}
+	if err != nil {
+		fields["error"] = err.Error()
+	}
+	addCaller(GetLogger(c), 2).WithFields(fields).Error("发生错误")
+}
+
+// Fatal 输出致命级别的日志并退出程序
+func Fatal(c context.Context, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Fatal(args...)
+}
+
+// Fatalf 使用格式化字符串输出致命级别的日志并退出程序
+func Fatalf(c context.Context, format string, args ...interface{}) {
+	addCaller(GetLogger(c), 2).Fatalf(format, args...)
+}
+
+// CloneContext 复制上下文中的关键信息到新上下文
+//
+// Which keys survive is decided by types.contextCloneAcrossDetach, which lives
+// next to where context keys are declared so that adding a key and deciding
+// its fate are the same edit. Keeping that decision here instead meant every
+// new key silently defaulted to being dropped.
+func CloneContext(ctx context.Context) context.Context {
+	newCtx := context.Background()
+
+	for _, k := range types.ContextKeysClonedAcrossDetach() {
+		if v := ctx.Value(k); v != nil {
+			newCtx = context.WithValue(newCtx, k, v)
+		}
+	}
+
+	// Preserve the active OpenTelemetry span across the rebuild. The Langfuse
+	// *Trace handle above carries the trace id, but span PARENTING flows through
+	// the OTel span context (trace.SpanFromContext), which CloneContext would
+	// otherwise drop — orphaning child spans opened after a CloneContext (e.g.
+	// the agent engine's agent.execute becoming a separate trace from the HTTP
+	// root). Re-inject the recording span so children stitch to the same trace.
+	if sp := trace.SpanFromContext(ctx); sp.IsRecording() {
+		newCtx = trace.ContextWithSpan(newCtx, sp)
+	}
+
+	return newCtx
+}
+
+// CloneContextWithoutTrace copies the same identity keys as CloneContext but
+// drops the Langfuse *Trace handle and the OpenTelemetry span. Use it for
+// background work that must keep tenant/session identity yet must not attach
+// child spans (Docker Engine HTTP, idle sweeps, image pulls kicked off after
+// a tool has returned) onto the originating chat trace.
+func CloneContextWithoutTrace(ctx context.Context) context.Context {
+	newCtx := context.Background()
+	for _, k := range types.ContextKeysClonedAcrossDetach() {
+		if k == types.LangfuseTraceContextKey {
+			continue
+		}
+		if v := ctx.Value(k); v != nil {
+			newCtx = context.WithValue(newCtx, k, v)
+		}
+	}
+	return newCtx
+}

internal/logger/logger_test.go

@@ -0,0 +1,304 @@
+package logger
+
+import (
+	"context"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/Tencent/WeKnora/internal/types"
+	"github.com/sirupsen/logrus"
+)
+
+func newEntry(level logrus.Level, msg string, data logrus.Fields) *logrus.Entry {
+	e := logrus.NewEntry(logrus.New())
+	e.Time = time.Date(2026, 5, 21, 10, 20, 30, 123_000_000, time.UTC)
+	e.Level = level
+	e.Message = msg
+	e.Data = data
+	return e
+}
+
+func TestAnsiStripWriter(t *testing.T) {
+	var buf strings.Builder
+	w := &ansiStripWriter{w: &buf}
+	in := []byte("\x1b[32mINFO\x1b[0m hello \x1b[31mERROR\x1b[0m")
+	n, err := w.Write(in)
+	if err != nil {
+		t.Fatalf("Write error: %v", err)
+	}
+	if n != len(in) {
+		t.Fatalf("Write n = %d, want %d", n, len(in))
+	}
+	if got := buf.String(); got != "INFO hello ERROR" {
+		t.Fatalf("stripped output = %q, want %q", got, "INFO hello ERROR")
+	}
+}
+
+func TestFormat_DefaultModeUnchanged(t *testing.T) {
+	f := &CustomFormatter{} // no template, no color
+	entry := newEntry(logrus.InfoLevel, "hello", logrus.Fields{
+		"request_id": "req-1",
+		"caller":     "logger_test.go:1[Test]",
+		"k1":         "v1",
+	})
+
+	out, err := f.Format(entry)
+	if err != nil {
+		t.Fatalf("Format returned error: %v", err)
+	}
+	got := string(out)
+
+	if !strings.HasPrefix(got, "INFO ") {
+		t.Errorf("expected INFO-prefixed default output, got %q", got)
+	}
+	for _, want := range []string{"2026-05-21 10:20:30.123", "req-1", "k1=v1", "logger_test.go:1[Test]", "hello"} {
+		if !strings.Contains(got, want) {
+			t.Errorf("default output missing %q: %s", want, got)
+		}
+	}
+	if !strings.HasSuffix(got, "\n") {
+		t.Errorf("default output should end with newline, got %q", got)
+	}
+}
+
+func TestFormat_TemplateReplacesAllPlaceholders(t *testing.T) {
+	f := &CustomFormatter{
+		Template:     "[%d] %level %thread %logger %traceId | %msg",
+		threadNeeded: true,
+	}
+	entry := newEntry(logrus.WarnLevel, "boom", logrus.Fields{
+		"request_id": "req-42",
+		"caller":     "x.go:9[Fn]",
+		"extra":      "ok",
+	})
+
+	out, err := f.Format(entry)
+	if err != nil {
+		t.Fatalf("Format error: %v", err)
+	}
+	got := string(out)
+
+	for _, want := range []string{
+		"[2026-05-21 10:20:30.123]",
+		"WARNING",
+		"x.go:9[Fn]",
+		"req-42",
+		"boom",
+		"extra=ok",
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("template output missing %q: %s", want, got)
+		}
+	}
+	for _, placeholder := range []string{"%d", "%level", "%thread", "%logger", "%traceId", "%msg"} {
+		if strings.Contains(got, placeholder) {
+			t.Errorf("placeholder %q not substituted: %s", placeholder, got)
+		}
+	}
+}
+
+func TestFormat_TemplateGoroutineIDSkippedWhenNotReferenced(t *testing.T) {
+	// 模板未引用 %thread 时，threadNeeded 应为 false，运行时不应取 goroutine ID。
+	// 这里通过观察输出中不含数字-only goroutine ID 段来间接验证；更重要的是确保不 panic。
+	f := &CustomFormatter{
+		Template:     "[%d] %level | %msg",
+		threadNeeded: false,
+	}
+	entry := newEntry(logrus.InfoLevel, "no-thread", nil)
+	if _, err := f.Format(entry); err != nil {
+		t.Fatalf("Format error: %v", err)
+	}
+}
+
+// TestFormat_ColorDoesNotPolluteMessage 是修复 colorize 误染 bug 的回归测试。
+// 旧实现对整行做 ReplaceAll(line, "INFO", colored)，会把消息正文里的 "INFO"
+// 一并染色；新实现只在 %level 替换位置注入颜色。
+func TestFormat_ColorDoesNotPolluteMessage(t *testing.T) {
+	f := &CustomFormatter{
+		ForceColor:   true,
+		Template:     "%level | %msg",
+		threadNeeded: false,
+	}
+	entry := newEntry(logrus.InfoLevel, "user INFO loaded", nil)
+
+	out, err := f.Format(entry)
+	if err != nil {
+		t.Fatalf("Format error: %v", err)
+	}
+	got := string(out)
+
+	// 输出中 ANSI 序列总数应恰好为 2（开头一对 color + reset），
+	// 而非旧实现下消息里的 "INFO" 也被替换导致出现 4 段。
+	const ansiOpen = "\033[32m" // green for INFO
+	const ansiReset = "\033[0m"
+	if strings.Count(got, ansiOpen) != 1 {
+		t.Errorf("expected exactly 1 green-open sequence, got %d in %q", strings.Count(got, ansiOpen), got)
+	}
+	if strings.Count(got, ansiReset) != 1 {
+		t.Errorf("expected exactly 1 reset sequence, got %d in %q", strings.Count(got, ansiReset), got)
+	}
+	// 消息正文中的 "INFO" 字面串应保持未染色（其前驱字符不是 ANSI 开头）。
+	idx := strings.Index(got, "user INFO loaded")
+	if idx < 0 {
+		t.Fatalf("message body not found verbatim in output: %q", got)
+	}
+}
+
+// TestFormat_TemplateNoCascadingReplace 验证使用 NewReplacer 单趟替换，
+// 字段值里含有占位符字面串（例如 traceId 值为 "%msg"）时不会被二次替换。
+func TestFormat_TemplateNoCascadingReplace(t *testing.T) {
+	f := &CustomFormatter{
+		Template:     "%traceId>%msg",
+		threadNeeded: false,
+	}
+	entry := newEntry(logrus.InfoLevel, "actual-msg", logrus.Fields{
+		"request_id": "%msg", // 恶意/巧合的字段值
+	})
+
+	out, err := f.Format(entry)
+	if err != nil {
+		t.Fatalf("Format error: %v", err)
+	}
+	got := strings.TrimRight(string(out), "\n")
+	want := "%msg>actual-msg"
+	if got != want {
+		t.Errorf("cascading-replace regression: got %q, want %q", got, want)
+	}
+}
+
+func TestLevelColorFor(t *testing.T) {
+	cases := map[logrus.Level]string{
+		logrus.DebugLevel: colorCyan,
+		logrus.InfoLevel:  colorGreen,
+		logrus.WarnLevel:  colorYellow,
+		logrus.ErrorLevel: colorRed,
+		logrus.FatalLevel: colorPurple,
+		logrus.TraceLevel: "",
+	}
+	for lvl, want := range cases {
+		if got := levelColorFor(lvl); got != want {
+			t.Errorf("levelColorFor(%v) = %q, want %q", lvl, got, want)
+		}
+	}
+}
+
+func TestCloneContextPreservesPrincipal(t *testing.T) {
+	t.Parallel()
+
+	ctx := types.WithPrincipal(context.Background(), types.EmbedSessionPrincipal(10000, "ch1", "sess1"))
+	cloned := CloneContext(ctx)
+
+	if got := types.SessionOwnerIDFromContext(cloned); got != "embed_session:10000:ch1:sess1" {
+		t.Fatalf("SessionOwnerIDFromContext(cloned) = %q", got)
+	}
+}
+
+func TestCloneContextPreservesTenantAPIKeyScope(t *testing.T) {
+	t.Parallel()
+
+	want := types.TenantAPIKeyScope{
+		KeyID:            7,
+		KnowledgeBaseIDs: types.StringArray{"kb-1"},
+	}
+	ctx := types.WithTenantAPIKeyScope(context.Background(), want)
+	cloned := CloneContext(ctx)
+
+	got, ok := types.TenantAPIKeyScopeFromContext(cloned)
+	if !ok {
+		t.Fatal("TenantAPIKeyScopeFromContext(cloned) = false, want true")
+	}
+	if got.KeyID != want.KeyID || !got.AllowsKnowledgeBase("kb-1") || got.AllowsKnowledgeBase("kb-2") {
+		t.Fatalf("cloned scope = %#v, want key_id=7 scoped to kb-1", got)
+	}
+}
+
+// setupSSEStream builds its async context through CloneContext, so dropping
+// this key here would silently re-key every session→sandbox binding onto the
+// tenant a shared agent borrowed — stranding the MicroVM at session deletion.
+func TestCloneContextPreservesSandboxTenantID(t *testing.T) {
+	t.Parallel()
+
+	const sessionOwner, agentOwner = uint64(7), uint64(99)
+
+	ctx := context.WithValue(context.Background(), types.TenantIDContextKey, agentOwner)
+	ctx = types.WithSandboxTenantID(ctx, sessionOwner)
+	cloned := CloneContext(ctx)
+
+	got, ok := types.SandboxTenantIDFromContext(cloned)
+	if !ok || got != sessionOwner {
+		t.Fatalf("SandboxTenantIDFromContext(cloned) = (%d, %v), want (%d, true)",
+			got, ok, sessionOwner)
+	}
+}
+
+// The agent-level memory opt-out is set before setupSSEStream clones, while
+// extraction and the explicit remember route run after. Losing the key here
+// would leave an agent that cannot read memory still writing to it.
+func TestCloneContextPreservesTheAgentMemoryOptOut(t *testing.T) {
+	t.Parallel()
+
+	optedOut := CloneContext(types.WithMemoryDisabled(context.Background()))
+	if types.MemoryAllowedForAgent(optedOut) {
+		t.Fatal("MemoryAllowedForAgent(cloned) = true, want the opt-out to survive the clone")
+	}
+
+	// The absence of the marker still has to read as allowed, so agents that
+	// never touched the switch keep their memory.
+	if !types.MemoryAllowedForAgent(CloneContext(context.Background())) {
+		t.Fatal("MemoryAllowedForAgent(cloned) = false for an unmarked context, want true")
+	}
+}
+
+// Document ingestion detaches mid-flight: knowledge_create hands processChunks
+// to a goroutine on a cloned context, and processChunks vectorises every chunk.
+// If the background mark does not survive, that work stops being visible to the
+// per-model concurrency governor and the ingestion storm it exists to contain
+// runs past it, starving interactive chat.
+func TestCloneContextKeepsBackgroundWorkThrottled(t *testing.T) {
+	t.Parallel()
+
+	if !types.IsBackgroundTask(CloneContext(types.WithBackgroundTask(context.Background()))) {
+		t.Fatal("IsBackgroundTask(cloned) = false, want background work to stay throttled across a detach")
+	}
+	if types.IsBackgroundTask(CloneContext(context.Background())) {
+		t.Fatal("IsBackgroundTask(cloned) = true for an unmarked context, want interactive work left ungated")
+	}
+}
+
+// An IM bot has no live client to click "Authorize", so losing this mark makes
+// the agent block on the OAuth wait for every unauthorized service instead of
+// replying with its one-shot notice.
+func TestCloneContextKeepsTheNonInteractiveOAuthMark(t *testing.T) {
+	t.Parallel()
+
+	if !types.IsMCPOAuthNonInteractive(CloneContext(types.WithMCPOAuthNonInteractive(context.Background()))) {
+		t.Fatal("IsMCPOAuthNonInteractive(cloned) = false, want the mark to survive a detach")
+	}
+	if types.IsMCPOAuthNonInteractive(CloneContext(context.Background())) {
+		t.Fatal("IsMCPOAuthNonInteractive(cloned) = true for an unmarked context, want interactive prompts to stay possible")
+	}
+}
+
+func TestCloneContextWithoutTraceDropsTheChatTrace(t *testing.T) {
+	t.Parallel()
+
+	const tenantID uint64 = 42
+	ctx := context.WithValue(context.Background(), types.TenantIDContextKey, tenantID)
+	ctx = context.WithValue(ctx, types.LangfuseTraceContextKey, "trace-handle")
+
+	kept := CloneContext(ctx)
+	if kept.Value(types.LangfuseTraceContextKey) != "trace-handle" {
+		t.Fatal("CloneContext must keep the Langfuse trace so same-request work stays nested")
+	}
+
+	detached := CloneContextWithoutTrace(ctx)
+	if detached.Value(types.LangfuseTraceContextKey) != nil {
+		t.Fatal("CloneContextWithoutTrace must drop the Langfuse trace so " +
+			"background sandbox RPCs do not join the chat tree")
+	}
+	got, _ := detached.Value(types.TenantIDContextKey).(uint64)
+	if got != tenantID {
+		t.Fatalf("TenantID = %d, want %d (identity must survive the detach)", got, tenantID)
+	}
+}