refactor(logger): support LOG_FORMAT template and harden level coloring

2026-05-21 15:42:10 +08:00
parent 39c9985c3b
commit 3d5b4c16fe
2 changed files with 217 additions and 0 deletions
@@ -0,0 +1,51 @@
+# 日志配置
+
+WeKnora 的日志由 `internal/logger` 统一管理，所有行为通过环境变量驱动，无需改代码。
+
+## 环境变量
+
+| 变量 | 是否必填 | 默认值 | 说明 |
+| --- | --- | --- | --- |
+| `LOG_LEVEL` | 否 | `debug` | 日志级别，取值 `debug` / `info` / `warn`(`warning`) / `error` / `fatal`，无效值回退到 `debug` |
+| `LOG_PATH`  | 否 | 空（仅打到 stdout；macOS `.app` 打包模式下落到 `~/Library/Logs/<AppName>/<AppName>.log`） | 落盘路径，启用后同时写 stdout 与该文件，文件按 lumberjack 滚动（单文件 50MB / 3 份 / 28 天 / 压缩归档） |
+| `LOG_FORMAT` | 否 | 空（沿用内置默认格式） | 自定义日志输出模板，支持下列占位符 |
+
+> 终端环境下 ANSI 颜色自动启用；非 TTY（容器日志采集、`docker logs` 重定向等）会自动关闭颜色，避免日志聚合/检索异常。
+
+## `LOG_FORMAT` 模板
+
+`LOG_FORMAT` 为空时使用内置默认格式（与历史行为一致）：
+
+```
+INFO [2026-05-21 10:20:30.123] [req-abc k1=v1] file.go:42[fn] | message body
+```
+
+配置 `LOG_FORMAT` 后启用模板模式，支持如下占位符：
+
+| 占位符 | 含义 |
+| --- | --- |
+| `%d`       | 时间戳（`2006-01-02 15:04:05.000`） |
+| `%level`   | 日志级别（`DEBUG` / `INFO` / `WARNING` / `ERROR` / `FATAL`），开启颜色时仅此占位符被染色 |
+| `%thread`  | 当前 goroutine ID。**未引用该占位符时不会调用 `runtime.Stack`，无额外开销** |
+| `%logger`  | caller 信息（`file.go:line[func]`），过长时从末尾截取后 50 字符 |
+| `%traceId` | 请求 ID（即上下文中的 `request_id`） |
+| `%msg`     | 消息正文 + 剩余结构化字段（`key=value`，按 key 升序拼接） |
+
+示例：
+
+```bash
+export LOG_FORMAT='[%d] %level %thread %logger %traceId | %msg'
+```
+
+输出（终端开启颜色时仅 `%level` 段着色）：
+
+```
+[2026-05-21 10:20:30.123] INFO 17 service.go:88[Handle] req-abc | hello extra=ok
+```
+
+### 实现细节与注意事项
+
+- 占位符替换使用 `strings.NewReplacer` 单趟扫描，前一个占位符的值即使包含其它占位符字面串（如 `request_id=%msg`）也不会被二次替换。
+- 级别染色在 `%level` 替换阶段直接注入 ANSI 颜色，**不会**误染消息正文中字面出现的 `INFO` / `ERROR` 等字符串。
+- 结构化字段（`logger.WithField` / `WithFields`）会被拼接到 `%msg` 之后，模板模式下暂不支持把任意字段抽出为独立占位符 — 若需 K/V 结构化检索，请直接关闭 `LOG_FORMAT` 使用默认格式。
+- `LOG_LEVEL` 与 `LOG_PATH` 的设置会在 `main` 加载 `.env` 后由 `logger.ConfigureFromEnv()` 重新生效。
@@ -0,0 +1,166 @@
+package logger
+
+import (
+	"strings"
+	"testing"
+	"time"
+
+	"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 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)
+		}
+	}
+}