From 7e1b4748230bdf4e75f88767b4faf7ca3daf61a7 Mon Sep 17 00:00:00 2001 From: Yun Date: Mon, 14 Sep 2026 00:14:30 +0800 Subject: [PATCH] =?UTF-8?q?=E6=9B=B4=E6=96=B0?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- compress.go | 39 ++++-- example/gin_server/main.go | 20 ++- filePath.go | 205 ++++++++++++++++++++++++++++-- format.go | 225 +++++++++++++++++++++++++++++---- go.mod | 2 +- go.sum | 4 +- loggerc.go | 86 +++++++++++-- loggerx.go | 197 ++++++++++++++++++++++++----- loggerx_features_bench_test.go | 22 ++++ loggerx_features_test.go | 31 ++++- loggerx_format_test.go | 187 +++++++++++++++++++++++++++ loggerx_globalstate_test.go | 102 +++++++++++++++ loggerx_prod_gaps_test.go | 188 +++++++++++++++++++++++++++ loggerx_wedge_test.go | 109 ++++++++++++++++ middleware/traceId.go | 90 +++++++++---- middleware/traceId_test.go | 154 ++++++++++++++++++++++ options.go | 103 ++++++++++++++- readme.md | 79 +++++++++++- remove.go | 73 ++++++++++- storage.go | 135 +++++++++++++++++--- 20 files changed, 1885 insertions(+), 166 deletions(-) create mode 100644 loggerx_format_test.go create mode 100644 loggerx_globalstate_test.go create mode 100644 loggerx_prod_gaps_test.go create mode 100644 loggerx_wedge_test.go create mode 100644 middleware/traceId_test.go diff --git a/compress.go b/compress.go index 410d684..3be4f0d 100644 --- a/compress.go +++ b/compress.go @@ -19,18 +19,6 @@ import ( // 2. 把文件改名成 名字_N.log（先改名，保证任何时刻文件都存在，崩溃也不丢数据） // 3. 交给后台协程压缩成 名字_N.log.gz，压缩成功后再删掉未压缩文件 -// nextIndex 返回下一个归档序号 -// 首次调用会先扫描目录里已有的 _N.log / _N.log.gz，避免覆盖上次运行的归档 -func (l *Logger) nextIndex() int { - l.idxOnce.Do(func() { - l.idx = l.maxIndexOnDisk() - }) - l.idxMu.Lock() - defer l.idxMu.Unlock() - l.idx++ - return l.idx -} - // maxIndexOnDisk 扫描日志目录，找出已经用掉的最大序号 func (l *Logger) maxIndexOnDisk() int { max := 0 @@ -74,8 +62,11 @@ func (l *Logger) archive(base, fileName string) (string, error) { for try := 0; try < 1000; try++ { idx := l.nextIndex() candidate := filepath.Join(dir, fmt.Sprintf("%s_%d.log", base, idx)) - if _, err := os.Stat(candidate); err == nil { - continue // 已存在，换一个序号 + // 占用判断必须同时看 .log 和 .log.gz： + // 压缩成功后只剩 .gz，只看 .log 会以为序号空着， + // 于是归档名撞上已有归档，后面 gzip 重命名会把老归档覆盖掉 + if indexInUse(base, idx) { + continue } if err := os.Rename(fileName, candidate); err != nil { return "", fmt.Errorf("归档日志文件失败 %s: %w", fileName, err) @@ -85,6 +76,18 @@ func (l *Logger) archive(base, fileName string) (string, error) { return "", fmt.Errorf("归档日志文件失败 %s: 找不到可用序号", fileName) } +// indexInUse 序号 idx 是否已被占用（.log 或 .log.gz 任一存在即算占用） +func indexInUse(base string, idx int) bool { + name := fmt.Sprintf("%s_%d.log", strings.TrimSuffix(base, ".log"), idx) + if _, err := os.Stat(name); err == nil { + return true + } + if _, err := os.Stat(name + ".gz"); err == nil { + return true + } + return false +} + // scheduleCompress 把压缩任务丢到后台，不阻塞写入路径 // 不压缩时什么也不做，归档文件保留为 .log func (l *Logger) scheduleCompress(path string) { @@ -101,6 +104,9 @@ func (l *Logger) scheduleCompress(path string) { }() } +// gzipTempSuffix 压缩临时文件后缀 +const gzipTempSuffix = ".gz.tmp" + // gzipFile 把 src 压缩成 src.gz，成功后删除 src // 先写临时文件再改名，避免半截 .gz 被当成完整归档 func gzipFile(src string, level int) error { @@ -151,6 +157,11 @@ func gzipFile(src string, level int) error { closeIn() // 删除源文件之前一定要先释放读句柄 dst := src + ".gz" + // 绝不覆盖已有归档：序号复用或并发写入时，覆盖等于直接销毁历史日志 + if _, err := os.Stat(dst); err == nil { + _ = os.Remove(tmp) + return fmt.Errorf("归档目标已存在，拒绝覆盖: %s", dst) + } if err := os.Rename(tmp, dst); err != nil { _ = os.Remove(tmp) return err diff --git a/example/gin_server/main.go b/example/gin_server/main.go index 478efaa..40ad19b 100644 --- a/example/gin_server/main.go +++ b/example/gin_server/main.go @@ -13,19 +13,25 @@ import ( func main() { ctx := context.Background() - log := loggerx.NewLogger(ctx, loggerx.SetToConsole()) + log := loggerx.NewLogger(ctx, + loggerx.SetToConsole(), + loggerx.SetGinLog(true), // 把 gin 自身的 access log 也收进日志文件 + ) // 进程退出前落盘并释放文件句柄 defer log.Close() - g := gin.Default() + g := gin.New() // 用 gin.New 而不是 gin.Default，避免 access log 与中间件重复记录 + g.Use(gin.Recovery()) - g.Use(middleware.SetGinTraceIdByLogger(log)) + // 生成/透传 trace id，并写回响应头 X-Trace-Id + g.Use(middleware.SetGinTraceId(log)) g.Use(middleware.SetGinParams(log)) - g.GET("/ping", func(ctx *gin.Context) { - log.Infof(ctx, "GET /ping") - ctx.JSON(200, gin.H{"message": "pong"}) + g.GET("/ping", func(c *gin.Context) { + // trace id 通过 request context 传给日志，便于串起整条链路 + log.Infof(c.Request.Context(), "GET /ping") + c.JSON(200, gin.H{"message": "pong", "trace_id": middleware.GetTraceId(c.Request.Context(), log.GetTraceField())}) }) - g.Run(":8080") + _ = g.Run(":8080") } diff --git a/filePath.go b/filePath.go index 9012342..c16d9a2 100644 --- a/filePath.go +++ b/filePath.go @@ -6,14 +6,21 @@ import ( "io" "os" "path/filepath" + "regexp" "strings" + "sync/atomic" "time" ) // 文件操作 -// errClosed 日志实例已关闭，不再接受新的文件写入 -var errClosed = errors.New("loggerx: 日志已关闭") +// ErrClosed 日志实例已关闭，不再接受新的文件写入 +// 导出它以便调用方用 errors.Is(err, loggerx.ErrClosed) 判断， +// 而不是去匹配错误字符串 +var ErrClosed = errors.New("loggerx: 日志已关闭") + +// errClosed 内部别名，保持既有引用不变 +var errClosed = ErrClosed // 每个文件的写缓冲大小：越大越省系统调用，代价是崩溃时可能丢最后一批日志 const fileBufSize = 32 * 1024 @@ -28,15 +35,51 @@ type logFile struct { // written 已写进文件的字节数（内存计数） // 按大小切割要判断是否该滚动：每条日志都 Stat 一次要花约 8µs， // 而写了多少字节自己最清楚，只在打开文件时 Stat 一次做基准即可 - written int64 + written int64 + // lastUsed 最后一次写入时间（UnixNano），用于回收长期不活跃的句柄 + lastUsed atomic.Int64 + // closed 句柄是否已关闭 + // 一旦关闭，Write 必须直接报错：否则数据只会进内存缓冲， + // 而这个句柄已经不在 filePath 里，刷新和关闭都找不到它 —— 日志静默丢失 + closed atomic.Bool fileName string // baseName 是 fileNameIn 的结果（不带大小切割的 _N 序号）， // 用于判断是否跨了时间切割边界，以及归档时取规范基名 baseName string } +// 句柄数量上界 +// +// 每个句柄 = 1 个文件描述符 + 32KB 缓冲，而 channel 名来自调用方（可能是 +// 请求 ID、租户名等）。不设上界时 1000 个不同 channel 名就是 1000 个 fd +// 加约 32MB 缓冲，Linux 默认 ulimit -n 1024 会直接 EMFILE，之后写入全失败 +const maxOpenHandles = 512 + +// idleHandleAge 多久没写入的句柄可以被回收 +const idleHandleAge = 30 * time.Minute + +// touch 记录一次写入，用于空闲回收 +func (f *logFile) touch() { + f.lastUsed.Store(time.Now().UnixNano()) +} + +// idle 句柄是否已经空闲超时 +func (f *logFile) idle() bool { + last := f.lastUsed.Load() + if last == 0 { + return false // 刚建好还没写过，先不回收 + } + return time.Since(time.Unix(0, last)) > idleHandleAge +} + // Write 写入缓冲，满了就落盘一次 func (f *logFile) Write(b []byte) (int, error) { + if f.closed.Load() { + // 已关闭的句柄绝不能再收数据：它可能已不在句柄表里， + // 进去的字节没有任何人会刷盘，而调用方看到的是成功 + return 0, ErrClosed + } + f.touch() written := 0 for len(b) > 0 { if f.pending == len(f.buf) { @@ -76,6 +119,7 @@ func (f *logFile) full(limit, n int) bool { } // writeFull 保证把整块数据写进文件（允许底层短写，循环补齐） +// 仅用于必须「要么全写、要么报错」且不在缓冲语义内的场景 func (f *logFile) writeFull(p []byte) error { for len(p) > 0 { n, err := f.file.Write(p) @@ -92,15 +136,38 @@ func (f *logFile) writeFull(p []byte) error { // Flush 把缓冲写入文件（不做 fsync） func (f *logFile) Flush() error { + return f.flushInternal(false) +} + +// flushInternal 落盘缓冲 +// keepOnError=true 时，写到一半失败也保留「没写成功的那段」并返回错误； +// 默认（false）则丢弃未成功的部分，避免错误恢复路径里反复重试同一段数据 +func (f *logFile) flushInternal(keepOnError bool) error { if f.pending == 0 { return nil } - if err := f.writeFull(f.buf[:f.pending]); err != nil { - // 保留未写成功的部分，下次继续 + n, err := f.file.Write(f.buf[:f.pending]) + // 关键：先把「已被内核确认写入」的字节从缓冲里去掉。 + // 否则下一次 Flush 会重发这段前缀，日志里出现重复/交错的半条记录， + // 同时 written 计数偏低会让 sizeSplit 误判，文件悄悄超限 + if n > 0 { + f.written += int64(n) + copy(f.buf, f.buf[n:f.pending]) + f.pending -= n + } + if err != nil { + if !keepOnError { + f.pending = 0 // 这段数据已经写坏了，不再重试，避免无限循环 + } return err } - f.written += int64(f.pending) - f.pending = 0 + if f.pending > 0 { + // 底层写了(0, nil)：不是合法行为，按短写处理 + if !keepOnError { + f.pending = 0 + } + return io.ErrShortWrite + } return nil } @@ -126,7 +193,14 @@ func (f *logFile) Sync() error { } // Close 落盘并关闭文件 +// 先置 closed 标记再关：避免关掉之后还有写入把数据塞进没人刷的缓冲 func (f *logFile) Close() error { + if f.closed.Swap(true) { + return nil // 重复关闭直接返回，避免二次 Close 污染错误信息 + } + if f.file == nil { + return nil + } return joinErrors([]error{f.Sync(), f.file.Close()}) } @@ -179,11 +253,46 @@ func (l *Logger) fileNameIn(channel, event string) string { } if channel != "" { - prefix = channel + "/" + prefix + prefix = sanitizeChannel(channel) + "/" + prefix } return l.option.dir + "/" + prefix + event + ".log" } +// channelNameRe channel 名允许的字符：字母数字与 . _ - +var channelNameRe = regexp.MustCompile(`^[A-Za-z0-9._-]{1,64}$`) + +// sanitizeChannel 清洗 channel 名，防止它被当成路径片段逃出日志目录 +// +// channel 名经常来自请求参数（tenant、requestID 等），直接拼进路径会出问题： +// +// Channel("../../etc") 会写到日志目录外面，而且逃出保留期清理的扫描范围 +// +// 非法字符统一替换成 '_'：既不丢这条日志，也不会写到别处去 +func sanitizeChannel(channel string) string { + if channelNameRe.MatchString(channel) && channel != "." && channel != ".." { + return channel + } + + out := make([]rune, 0, len(channel)) + for _, r := range channel { + switch { + case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r >= '0' && r <= '9', + r == '.', r == '_', r == '-': + out = append(out, r) + default: + out = append(out, '_') + } + } + s := strings.Trim(string(out), ".") + if s == "" { + s = "channel" + } + if len(s) > 64 { + s = s[:64] + } + return s +} + // 新建文件 func (l *Logger) getFile(event string) (*logFile, error) { return l.getFileTo(l.channel, event) @@ -210,6 +319,16 @@ func (l *Logger) getFileTo(channel, event string) (*logFile, error) { return nil, errClosed } + // 上界保护：句柄数已达上限时先回收空闲句柄，仍不够就明确报错， + // 而不是无声地把内存和 fd 吃光（channel 名来自调用方，可能是无限的） + if len(l.filePath) >= maxOpenHandles { + l.evictIdleLocked(true) + if len(l.filePath) >= maxOpenHandles { + return nil, fmt.Errorf("%w: 已打开 %d 个日志文件句柄，请检查是否在滥用 Channel（如把请求 ID 当 channel 名）", + errTooManyHandles, len(l.filePath)) + } + } + lf, err := l.newFile(key) if err != nil { return nil, err @@ -219,6 +338,65 @@ func (l *Logger) getFileTo(channel, event string) (*logFile, error) { return lf, nil } +// errTooManyHandles 打开的句柄数超限 +var errTooManyHandles = errors.New("loggerx: 日志文件句柄数超过上限") + +// evictIdleLocked 回收空闲句柄（调用方必须持有 mu 写锁） +// force=false 时只回收「确实空闲」的；force=true 时在空闲句柄用尽后 +// 按最早使用顺序继续淘汰（此时仍会先落盘 pending 数据，不丢日志） +func (l *Logger) evictIdleLocked(force bool) int { + type cand struct { + key fileKey + f *logFile + used int64 + } + + cands := make([]cand, 0, len(l.filePath)) + for k, f := range l.filePath { + if f == nil { + delete(l.filePath, k) + continue + } + used := f.lastUsed.Load() + if !force && !f.idle() { + continue + } + cands = append(cands, cand{key: k, f: f, used: used}) + } + + // 先淘汰最久没用的 + for i := 1; i < len(cands); i++ { + for j := i; j > 0 && cands[j].used < cands[j-1].used; j-- { + cands[j], cands[j-1] = cands[j-1], cands[j] + } + } + + n := 0 + for _, c := range cands { + // 关闭会先把缓冲刷盘，因此不会丢日志 + if err := c.f.Close(); err != nil { + l.reportError(fmt.Errorf("loggerx: 回收日志句柄失败 %s: %w", c.f.fileName, err)) + continue + } + delete(l.filePath, c.key) + n++ + } + return n +} + +// sweepIdleHandles 定期回收空闲句柄（由清理协程调用） +func (l *Logger) sweepIdleHandles() error { + // 必须先拿 writeMu：回收会先落盘再关句柄，而「所有文件 I/O 都在 writeMu 内」 + // 是本包的核心不变式，破坏它会和正在进行的写入撞到一起 + l.writeMu.Lock() + defer l.writeMu.Unlock() + + l.mu.Lock() + defer l.mu.Unlock() + l.evictIdleLocked(false) + return nil +} + // newFile 打开新文件；如果目标文件已经超过大小上限，就先把旧文件归档再开新序号 func (l *Logger) newFile(key fileKey) (*logFile, error) { limit := l.option.sizeSplit @@ -274,7 +452,9 @@ func (l *Logger) openNewFileIndexed(key fileKey) (*logFile, error) { base := l.fileNameIn(key.channel, key.event) for try := 0; try < 1000; try++ { idx := l.nextIndex() - if _, err := os.Stat(numberedName(base, idx)); err == nil { + // 同时看 .log 与 .log.gz：压缩成功后只剩 .gz， + // 漏看会导致新文件撞上已有归档名 + if indexInUse(base, idx) { continue // 序号已被占用，换下一个 } return l.openNumberedFile(key, idx) @@ -292,9 +472,12 @@ func (l *Logger) openFileWithIndex(key fileKey, idx int) (*logFile, error) { return nil, err } } - file, err := os.OpenFile(fileName, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644) + // O_EXCL：序号是否可用由调用方（indexInUse）保证，这里再兜一层。 + // 绝不能用 O_APPEND 打开别人的归档：那会和正在读取该文件的压缩任务互相踩， + // 而且会产生「半条记录 + 整条记录」的坏数据 + file, err := os.OpenFile(fileName, os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0644) if err != nil { - return nil, fmt.Errorf("打开日志文件失败 %s: %w", fileName, err) + return nil, fmt.Errorf("创建归档日志文件失败 %s: %w", fileName, err) } lf := &logFile{ file: file, diff --git a/format.go b/format.go index 825f153..00cf760 100644 --- a/format.go +++ b/format.go @@ -7,25 +7,51 @@ import ( "fmt" "path/filepath" "runtime" + "sort" "strconv" "strings" "time" ) -// basePath 进程工作目录（用于把绝对路径裁成相对路径） -// 只算一次并缓存：filepath.Abs 每次都要走系统调用，而它每条日志都会被用到 +// resolveBasePath 计算进程工作目录（用于把绝对路径裁成相对路径） +// 只在 NewLogger 里算一次：filepath.Abs 要走系统调用，而每条日志都会用到 +func resolveBasePath() string { + p, err := filepath.Abs("./") + if err != nil { + return "" + } + return strings.ReplaceAll(p, "\\", "/") +} + +// basePath 进程工作目录 +// 值放在共享指针里，Channel()/WriteAsync() 拷贝出的实例才能看到同一个结果 func (l *Logger) basePath() string { - l.basePathOnce.Do(func() { - p, err := filepath.Abs("./") - if err != nil { - p = "" - } - l.basePathVal = strings.ReplaceAll(p, "\\", "/") - }) - return l.basePathVal + if l.basePathVal == nil { + return "" + } + return *l.basePathVal +} + +// levelOf 事件名 -> 级别 +func levelOf(event string) Level { + switch event { + case "debug": + return LevelDebug + case "warn": + return LevelWarn + case "error": + return LevelError + default: + return LevelInfo + } } func (l *Logger) logger(ctx context.Context, event string, v ...any) { + // 级别过滤：低于设定级别的日志直接丢弃，连 JSON 都不序列化 + if levelOf(event) < l.option.minLevel { + return + } + // 调用方可能是 log 包（Logger.Write -> logger），所以这里取第 2 层 pc, file, line, ok := runtime.Caller(2) @@ -46,9 +72,14 @@ func (l *Logger) logger(ctx context.Context, event string, v ...any) { } // error 转成带堆栈的字符串（%+v 会带上 pkg/errors 的调用栈） - for idx, val := range v { + // 注意：这里会写进调用方传入的切片，因此先复制一份，不改调用方的内存 + args := v + for idx, val := range args { if _, isErr := val.(error); isErr { - v[idx] = fmt.Sprintf("%+v", val) + if &args[0] == &v[0] { + args = append([]any(nil), v...) + } + args[idx] = fmt.Sprintf("%+v", val) } } @@ -58,29 +89,169 @@ func (l *Logger) logger(ctx context.Context, event string, v ...any) { } fd := FormatData{ + Level: event, Time: nowTime, File: file + ":" + strconv.Itoa(line), Func: funcName, Gid: gid, - Content: v, + Content: args, TraceId: traceId, Expand: l.option.expandData, } - fdb := marshalLog(fd, nowTime, file, line, l.option.escapeHTML, gid, traceId) + line1 := l.marshalLine(fd, nowTime, file, line, gid, traceId) - fdb = append([]byte("\n["+event+"]"), fdb...) - - _, _ = l.write(event, fdb) + // 一条日志 = 一行完整合法的 JSON（+ 换行）， + // 这样 Fluent Bit / Vector / Loki / jq 等采集端可以直接解析。 + // 旧实现写成 "\n[info]{...}"：既不是 JSON 行，也没有行尾换行 + if _, err := l.write(event, line1); err != nil { + l.reportError(fmt.Errorf("loggerx: 写入日志失败: %w", err)) + } if l.option.errorToInfo && event == "error" { - _, _ = l.write("info", fdb) + if _, err := l.write("info", line1); err != nil { + l.reportError(fmt.Errorf("loggerx: 写入 info 日志失败: %w", err)) + } } } -// marshalLog 序列化日志内容 +// marshalLine 按当前配置（格式 + 前缀）渲染一条日志，返回以换行结尾的一行 +// +// 前缀/换行都 append 进目标切片，不额外分配一个容器再拷贝： +// 这条路径每条日志都走，多一次分配就会体现在吞吐上 +func (l *Logger) marshalLine(fd FormatData, nowTime, file string, line int, gid, traceId string) []byte { + prefix := l.option.prefix + var body []byte + if l.option.format == FormatText { + body = marshalText(fd) + } else { + body = marshalLog(fd, nowTime, file, line, l.option.escapeHTML, gid, traceId) + body = bytes.TrimRight(body, "\n") + } + + out := make([]byte, 0, len(prefix)+len(body)+1) + out = append(out, prefix...) + out = append(out, body...) + return append(out, '\n') +} + +// marshalText 把一条日志渲染成单行紧凑文本 +// 形如：level=info time=2026-01-02 15:04:05.000000 file=/a.go:12 func=main gid=7 content=hi +// 值里含空格/引号/换行时用 %q 包起来，保证「一行一条」且不歧义 +// +// 用 append 到 []byte 而不是 strings.Builder + Sprintf： +// 文本格式的意义就是便宜，走反射/格式化会把省下的 JSON 成本又花回去 +func marshalText(fd FormatData) []byte { + var buf []byte + buf = append(buf, "level="...) + buf = append(buf, fd.Level...) + buf = appendTextField(buf, "time", fd.Time) + buf = appendTextField(buf, "file", fd.File) + if fd.Func != "" { + buf = appendTextField(buf, "func", fd.Func) + } + if fd.Gid != "" { + buf = appendTextField(buf, "gid", fd.Gid) + } + if fd.TraceId != "" { + buf = appendTextField(buf, "traceId", fd.TraceId) + } + buf = append(buf, " content="...) + buf = appendContent(buf, fd.Content) + for _, k := range sortedKeys(fd.Expand) { + buf = appendTextField(buf, k, fd.Expand[k]) + } + return buf +} + +// appendTextField 追加一个 key=value 字段，必要时加引号 +func appendTextField(buf []byte, key, val string) []byte { + buf = append(buf, ' ') + buf = append(buf, key...) + buf = append(buf, '=') + if val == "" { + return append(buf, `""`...) + } + if strings.ContainsAny(val, " \t\"'=\n\r") { + return strconv.AppendQuote(buf, val) + } + return append(buf, val...) +} + +// appendContent 渲染 content（多个参数用空格分隔） +// 单个值走快速路径，避免 fmt 的反射开销 +func appendContent(buf []byte, v any) []byte { + switch val := v.(type) { + case nil: + return append(buf, `""`...) + case []any: + for i, item := range val { + if i > 0 { + buf = append(buf, ' ') + } + buf = appendValue(buf, item) + } + if len(val) == 0 { + buf = append(buf, `""`...) + } + return buf + case []string: + if len(val) == 0 { + return append(buf, `""`...) + } + return append(buf, strings.Join(val, " ")...) + case string: + return appendValue(buf, val) + default: + return appendValue(buf, val) + } +} + +// appendValue 渲染单个值，需要时加引号 +func appendValue(buf []byte, v any) []byte { + var s string + switch val := v.(type) { + case string: + s = val + case error: + s = val.Error() + case fmt.Stringer: + s = val.String() + case int: + return strconv.AppendInt(buf, int64(val), 10) + case int64: + return strconv.AppendInt(buf, val, 10) + case bool: + return strconv.AppendBool(buf, val) + default: + s = fmt.Sprintf("%v", v) + } + if s == "" { + return append(buf, `""`...) + } + if strings.ContainsAny(s, " \t\"'=\n\r") { + return strconv.AppendQuote(buf, s) + } + return append(buf, s...) +} + +// sortedKeys 让 map 输出顺序稳定，便于 diff 与测试 +func sortedKeys(m map[string]string) []string { + if len(m) == 0 { + return nil + } + keys := make([]string, 0, len(m)) + for k := range m { + keys = append(keys, k) + } + sort.Strings(keys) + return keys +} + +// marshalLog 序列化一条日志为 JSON（返回以换行结尾） +// // json 序列化失败时（chan/func 等不可序列化类型，或循环引用）不能静默丢弃， -// 否则只会留下一行没有内容的 "["+event+"]"，需要降级成可读的文本 +// 否则会留下一行没有内容的坏记录，需要降级成可读文本 func marshalLog(fd FormatData, nowTime, file string, line int, escapeHTML bool, gid, traceId string) []byte { var ( b []byte @@ -96,11 +267,12 @@ func marshalLog(fd FormatData, nowTime, file string, line int, escapeHTML bool, b = bytes.TrimRight(buf.Bytes(), "\n") } if err == nil { - return b + return append(b, '\n') } // 降级：逐字段尝试，失败的内容用 %+v 兜底 fallback := FormatData{ + Level: fd.Level, Time: nowTime, File: file + ":" + strconv.Itoa(line), Func: fd.Func, @@ -110,11 +282,11 @@ func marshalLog(fd FormatData, nowTime, file string, line int, escapeHTML bool, Expand: fd.Expand, } if fb, ferr := json.Marshal(fallback); ferr == nil { - return fb + return append(fb, '\n') } - return []byte(fmt.Sprintf(`{"time":%q,"content":%q,"marshal_error":%q}`, - nowTime, fmt.Sprintf("%+v", fd.Content), err.Error())) + return []byte(fmt.Sprintf("{\"level\":%q,\"time\":%q,\"content\":%q,\"marshal_error\":%q}\n", + fd.Level, nowTime, fmt.Sprintf("%+v", fd.Content), err.Error())) } // stringifyValues 把不可序列化的值转成字符串 @@ -128,6 +300,8 @@ func stringifyValues(v any) []string { out = append(out, fmt.Sprintf("%+v", item)) } return out + case []string: + return val default: return []string{fmt.Sprintf("%+v", val)} } @@ -146,13 +320,14 @@ func getGID() string { return string(b[:idx]) } +// FormatData 一条日志的落盘结构 type FormatData struct { + Level string `json:"level,omitempty"` Time string `json:"time,omitempty"` File string `json:"file,omitempty"` Func string `json:"func,omitempty"` Gid string `json:"gid,omitempty"` Content interface{} `json:"content,omitempty"` TraceId string `json:"traceId,omitempty"` - Stack string `json:"stack,omitempty"` Expand map[string]string `json:"expand,omitempty"` } diff --git a/go.mod b/go.mod index 311e6e2..3775b22 100644 --- a/go.mod +++ b/go.mod @@ -4,7 +4,7 @@ go 1.20 require ( github.com/gin-gonic/gin v1.9.1 - github.com/satori/go.uuid v1.2.0 + github.com/google/uuid v1.6.0 ) require ( diff --git a/go.sum b/go.sum index 9d91969..7ecda00 100644 --- a/go.sum +++ b/go.sum @@ -26,6 +26,8 @@ github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaS github.com/google/go-cmp v0.5.5 h1:Khx7svrCpmxxtHBq5j2mp/xVjsi8hQMfNLvJFAlrGgU= github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= +github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= +github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/json-iterator/go v1.1.12 h1:PV8peI4a0ysnczrg+LtxykD8LfKY9ML6u2jnxaEnrnM= github.com/json-iterator/go v1.1.12/go.mod h1:e30LSqwooZae/UwlEbR2852Gd8hjQvJoHmT4TnhNGBo= github.com/klauspost/cpuid/v2 v2.0.9/go.mod h1:FInQzS24/EEf25PyTYn52gqo7WaD8xa0213Md/qVLRg= @@ -44,8 +46,6 @@ github.com/pelletier/go-toml/v2 v2.0.8 h1:0ctb6s9mE31h0/lhu+J6OPmVeDxJn+kYnJc2jZ github.com/pelletier/go-toml/v2 v2.0.8/go.mod h1:vuYfssBdrU2XDZ9bYydBu6t+6a6PYNcZljzZR9VXg+4= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= -github.com/satori/go.uuid v1.2.0 h1:0uYX9dsZ2yD7q2RtLRtPSdGDWzjeM3TbMJP9utgA0ww= -github.com/satori/go.uuid v1.2.0/go.mod h1:dA0hQrYB0VpLJoorglMZABFdXlWrHn1NEOzdhQKdks0= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo= diff --git a/loggerc.go b/loggerc.go index dbabd12..f27fcc1 100644 --- a/loggerc.go +++ b/loggerc.go @@ -3,40 +3,100 @@ package loggerx import ( "context" "fmt" + "io" + "sync" + "sync/atomic" ) -var loggerc *Logger +// 包级默认实例 +// +// 两个刻意的设计： +// 1. 惰性初始化：import 一个日志库不该产生副作用（旧实现在 init 里 NewLogger， +// 等于仅仅 import 就劫持全局 stdlib log、还起了几个后台 goroutine） +// 2. 指针原子发布：NewLoggerc 不做「就地改字段」，而是按现有配置建一个新实例 +// 再整体换上。就地改会让并发打日志的读方看到半改状态， +// expandData 这种 map 更会直接触发 fatal error: concurrent map read and map write +var ( + loggercOnce sync.Once + loggercPtr atomic.Pointer[Logger] +) -func init() { - loggerc = NewLogger(context.Background()) +// loggercDefault 返回包级实例，必要时创建 +func loggercDefault() *Logger { + loggercOnce.Do(func() { + loggercPtr.Store(NewLogger(context.Background(), SetAsGlobalLog())) + }) + if l := loggercPtr.Load(); l != nil { + return l + } + // CloseLoggerc 之后又有人用包级函数：重新建一个默认实例 + l := NewLogger(context.Background(), SetAsGlobalLog()) + loggercPtr.Store(l) + return l } +// NewLoggerc 配置包级实例 +// 在现有配置基础上追加选项，构造新实例后原子替换，因此可与并发日志调用共存 +// （替换瞬间可能有极少几条日志落进旧实例） func NewLoggerc(ctx context.Context, opts ...Option) { + base := loggercDefault() + + // 复制一份选项再改：绝不动正在被并发读取的那一份 + opt := base.option + opt.drivers = append([]io.Writer(nil), base.option.drivers...) + opt.expandData = make(map[string]string, len(base.option.expandData)) + for k, v := range base.option.expandData { + opt.expandData[k] = v + } for _, apply := range opts { - apply(&loggerc.option) + apply(&opt) + } + if ctx == nil { + ctx = context.Background() + } + + old := loggercPtr.Load() + next := NewLogger(ctx, func(o *loggerOption) { *o = opt }) + // NewLogger 只在实例创建时决定要不要起刷盘协程，走的是入参选项， + // 这里已经通过闭包把完整 opt 传进去了，无需额外处理 + loggercPtr.Store(next) + + // 旧实例必须收掉，否则后台 goroutine 与文件句柄会一直累积 + if old != nil && old != next { + _ = old.Close() } } +// CloseLoggerc 关闭包级实例（并还原全局 stdlib log） +// 建议在 main 退出前调用，否则包级实例缓冲里的日志（最多 32KB）不会落盘 +// 之后再次调用包级函数会自动新建一个默认实例，不会把包级 API 永久废掉 +func CloseLoggerc() error { + l := loggercPtr.Load() + if l == nil { + return nil + } + err := l.Close() + loggercPtr.Store(nil) + loggercOnce = sync.Once{} + return err +} + func Channel(ch string) (r *Logger) { - rr := *loggerc - rr.channel = ch - return &rr + return loggercDefault().Channel(ch) } func Info(ctx context.Context, v ...any) { - loggerc.logger(ctx, "info", v...) + loggercDefault().logger(ctx, "info", v...) } func Infof(ctx context.Context, format string, v ...any) { - s := fmt.Sprintf(format, v...) - loggerc.logger(ctx, "info", s) + loggercDefault().logger(ctx, "info", fmt.Sprintf(format, v...)) } func Error(ctx context.Context, v ...any) { - loggerc.logger(ctx, "error", v...) + loggercDefault().logger(ctx, "error", v...) } func Errorf(ctx context.Context, format string, v ...any) { - s := fmt.Sprintf(format, v...) - loggerc.logger(ctx, "error", s) + loggercDefault().logger(ctx, "error", fmt.Sprintf(format, v...)) } diff --git a/loggerx.go b/loggerx.go index 539b033..9bacf71 100644 --- a/loggerx.go +++ b/loggerx.go @@ -25,6 +25,7 @@ type Logger struct { filePath map[fileKey]*logFile // 每个 (channel,event) 一个句柄 mu *sync.RWMutex // 保护 filePath writeMu *sync.Mutex // 串行化文件写入（bufio 不是并发安全的） + driverMu *sync.Mutex // 串行化额外驱动：用户 driver 往往不是并发安全的 option loggerOption channel string writeType writeType // 是否异步落盘，这里作用范围是本条，优先判断这里 @@ -33,22 +34,120 @@ type Logger struct { closed *atomic.Bool // 是否已经关闭：关闭后再写不再新开句柄 done chan struct{} // 通用关闭信号（delete / ctx 相关 goroutine 用） workerDone chan struct{} // 异步消费 goroutine 退出信号 - closing chan struct{} // 异步投递关闭信号：只关一次 // 异步队列相关的整块状态都挂在指针后面：Logger 会被 Channel()/WriteAsync() // 浅拷贝，如果状态直接放在 Logger 里，拷贝出的实例就会各看各的 // （曾经因此让 Close 看不到真正的队列，白等一场、最后一条日志丢失） async *asyncCtl - // basePath 缓存（见 format.go basePath），避免每条日志都算一次 filepath.Abs - basePathOnce *sync.Once - basePathVal string + // basePath 缓存：值是共享指针，拷贝出的实例才能看到同一个基路径 + basePathVal *string - // 归档压缩相关状态（同样挂在指针后面供拷贝共享） - idxOnce *sync.Once // 归档序号只从目录里初始化一次 - idxMu *sync.Mutex // 保护 idx - idx int // 归档序号 - compWg *sync.WaitGroup // 后台压缩协程计数，Close 需要等它们收尾 + // 归档序号状态：必须整块共享，否则 Channel()/WriteAsync() 拷贝出来的实例 + // 会各自从 0 开始数，选出已被占用的序号，把已有归档覆盖掉 + idxState *idxCtl + + // 后台压缩协程计数：Close 需要等它们收尾，否则读归档会读到半截 .gz + compWg *sync.WaitGroup +} + +// idxCtl 归档序号的共享状态 +type idxCtl struct { + once *sync.Once + mu *sync.Mutex + n int +} + +// nextIndex 返回下一个归档序号（首次调用时从目录里扫描续号） +func (l *Logger) nextIndex() int { + l.idxState.once.Do(func() { + l.idxState.n = l.maxIndexOnDisk() + }) + l.idxState.mu.Lock() + defer l.idxState.mu.Unlock() + l.idxState.n++ + return l.idxState.n +} + +// 全局 stdlib log / gin 写手的接管登记信息 +var ( + globalLogOwner atomic.Pointer[Logger] // 当前接管全局 log 的实例 + origLogWriter atomic.Value // 进程最初（首次接管前）的 writer，只写一次 + globalLogMu sync.Mutex + + ginOwner atomic.Pointer[Logger] + origGinOut atomic.Value // 首次接管前的 gin.DefaultWriter + origGinErr atomic.Value // 首次接管前的 gin.DefaultErrorWriter + globalGinMu sync.Mutex +) + +// logWriterAdapter 让 io.Writer 能被安全地存进 atomic.Value +type logWriterAdapter struct{ w io.Writer } + +// takeOverGlobalLog 接管全局 stdlib log，只记录一次「最初」的 writer +func (l *Logger) takeOverGlobalLog() { + globalLogMu.Lock() + defer globalLogMu.Unlock() + + // 无论中间被接管几次，origLogWriter 永远是进程最初那个 writer。 + // 旧实现记的是「上一个持有者」，于是 L1->L2->Close(L2) 会把全局 log + // 还原成 L1，而 L1 也可能已关闭 —— 那正是这套机制要避免的丢日志场景 + if t := origLogWriter.Load(); t == nil { + origLogWriter.Store(logWriterAdapter{w: log.Writer()}) + } + log.SetOutput(l) + log.SetFlags(log.LstdFlags | log.Llongfile | log.Lmicroseconds) + globalLogOwner.Store(l) +} + +// releaseGlobalLog 如果全局 log 还指向自己，就还原成最初的 writer +// +// Close 时必须做：否则 Close 之后的 stdlib log 会写进已关闭实例， +// 被 ErrClosed 拒绝后静默丢失，运维完全看不到 +func (l *Logger) releaseGlobalLog() { + globalLogMu.Lock() + defer globalLogMu.Unlock() + + if cur := globalLogOwner.Load(); cur == nil || cur != l { + return + } + if v := origLogWriter.Load(); v != nil { + log.SetOutput(v.(logWriterAdapter).w) + } + globalLogOwner.Store(nil) +} + +// takeOverGinWriters 接管 gin 的默认写手 +// 把 os.Stdout 放前面：MultiWriter 遇到第一个错误就短路， +// 若先写 l 且 l 出错（磁盘满 / 已关闭），gin 连控制台输出和 Recovery 堆栈都会一起消失 +func (l *Logger) takeOverGinWriters() { + globalGinMu.Lock() + defer globalGinMu.Unlock() + + if v := origGinOut.Load(); v == nil { + origGinOut.Store(logWriterAdapter{w: gin.DefaultWriter}) + origGinErr.Store(logWriterAdapter{w: gin.DefaultErrorWriter}) + } + gin.DefaultWriter = io.MultiWriter(os.Stdout, l) + gin.DefaultErrorWriter = io.MultiWriter(os.Stdout, l) + ginOwner.Store(l) +} + +// releaseGinWriters 还原 gin 的默认写手 +func (l *Logger) releaseGinWriters() { + globalGinMu.Lock() + defer globalGinMu.Unlock() + + if cur := ginOwner.Load(); cur == nil || cur != l { + return + } + if v := origGinOut.Load(); v != nil { + gin.DefaultWriter = v.(logWriterAdapter).w + } + if v := origGinErr.Load(); v != nil { + gin.DefaultErrorWriter = v.(logWriterAdapter).w + } + ginOwner.Store(nil) } // asyncCtl 异步队列的共享控制块：所有拷贝共享同一份 @@ -88,36 +187,47 @@ func NewLogger(ctx context.Context, opts ...Option) *Logger { panic("文件夹权限不足") } - l := &Logger{ - ctx: ctx, - filePath: make(map[fileKey]*logFile), - mu: &sync.RWMutex{}, - writeMu: &sync.Mutex{}, - option: opt, - writeType: writeTypeDefault, - closeOnce: &sync.Once{}, - closed: &atomic.Bool{}, - done: make(chan struct{}), - workerDone: make(chan struct{}), - async: &asyncCtl{}, - basePathOnce: &sync.Once{}, - idxOnce: &sync.Once{}, - idxMu: &sync.Mutex{}, - compWg: &sync.WaitGroup{}, + // 构造函数允许 ctx 为 nil（调用方常把可选 ctx 直接传进来）， + // 但后台 goroutine 会调 ctx.Done()，nil 接口会 panic，这里统一兜底。 + // 另外提醒：这个 ctx 是「实例生命周期」句柄，应当传进程级 ctx， + // 不要传请求级 ctx —— 请求结束会让清理协程提前退出 + if ctx == nil { + ctx = context.Background() } - log.SetOutput(l) - log.SetFlags(log.LstdFlags | log.Llongfile | log.Lmicroseconds) // log.Lshortfile | log.LUTC + l := &Logger{ + ctx: ctx, + filePath: make(map[fileKey]*logFile), + mu: &sync.RWMutex{}, + writeMu: &sync.Mutex{}, + driverMu: &sync.Mutex{}, + option: opt, + writeType: writeTypeDefault, + closeOnce: &sync.Once{}, + closed: &atomic.Bool{}, + done: make(chan struct{}), + workerDone: make(chan struct{}), + async: &asyncCtl{}, + basePathVal: new(string), + idxState: &idxCtl{once: &sync.Once{}, mu: &sync.Mutex{}}, + compWg: &sync.WaitGroup{}, + } + *l.basePathVal = resolveBasePath() + + // 把全局 stdlib log 的输出接管到本实例（可选，默认不接管） + // 生产建议：日志库不应该在 import 或 NewLogger 时静默劫持宿主的全局 log， + // 多实例场景下后建的会把先建的顶掉，Close 之后全局 log 还会指向已关闭实例 + if opt.asGlobalLog { + l.takeOverGlobalLog() + } // 保存Gin日志写入到文件+控制台 if opt.isGinLog { - gin.DefaultWriter = io.MultiWriter(l, os.Stdout) - gin.DefaultErrorWriter = io.MultiWriter(l, os.Stdout) + l.takeOverGinWriters() } // 日志删除 go l.delete() - // 定时刷盘 if opt.flushEvery > 0 { go l.flushLoop() @@ -191,12 +301,37 @@ func (l *Logger) Close() error { // 4. 等后台压缩协程收尾：不等的话 Close 返回后去读归档会读到半截 .gz l.compWg.Wait() - // 5. 最后再发通用关闭信号，让 delete / ctx 相关 goroutine 退出 + // 5. 如果全局 log / gin 写手还指向自己，还原成最初的那个 + // 否则 Close 之后 stdlib log 会写进已关闭实例并被静默丢弃 + l.releaseGlobalLog() + l.releaseGinWriters() + + // 6. 最后再发通用关闭信号，让 delete / ctx 相关 goroutine 退出 close(l.done) }) return err } +// reportError 上报日志库自身的内部错误 +// +// 这是运维唯一能看到「磁盘满 / 句柄失效 / 归档失败 / 刷盘超时」的通道： +// 注册了 SetErrorHandler 就交给它，否则退回 stderr，至少不会完全静默。 +// 回调自身 panic 会被吞掉，绝不能让错误处理把调用方带崩。 +func (l *Logger) reportError(err error) { + if err == nil { + return + } + fn := l.option.onError + if fn == nil { + fmt.Fprintln(os.Stderr, err) + return + } + func() { + defer func() { _ = recover() }() + fn(err) + }() +} + // 强制刷盘：只 flush 缓存数据，文件继续可写 // 与写入并发调用是安全的（内部会先拿到写锁） func (l *Logger) MustSync() error { diff --git a/loggerx_features_bench_test.go b/loggerx_features_bench_test.go index a36ae06..91ca145 100644 --- a/loggerx_features_bench_test.go +++ b/loggerx_features_bench_test.go @@ -51,3 +51,25 @@ func BenchmarkWriteShortFlushInterval(b *testing.B) { l.Infof(ctx, "hello %d", i) } } + +// text 格式（不走 encoding/json，应该比默认 JSON 便宜） +func BenchmarkTextFormat(b *testing.B) { + l := benchLogger(b, loggerx.SetFormat(loggerx.FormatText)) + ctx := context.Background() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + l.Infof(ctx, "hello %d", i) + } +} + +// 带前缀的 JSON（每行多一次拼接） +func BenchmarkJSONWithPrefix(b *testing.B) { + l := benchLogger(b, loggerx.SetPrefix("[svc] ")) + ctx := context.Background() + b.ReportAllocs() + b.ResetTimer() + for i := 0; i < b.N; i++ { + l.Infof(ctx, "hello %d", i) + } +} diff --git a/loggerx_features_test.go b/loggerx_features_test.go index 991beef..f85ac72 100644 --- a/loggerx_features_test.go +++ b/loggerx_features_test.go @@ -3,6 +3,7 @@ package loggerx_test import ( "compress/gzip" "context" + "encoding/json" "fmt" "io" "os" @@ -145,8 +146,9 @@ func TestCompressedArchiveIsReadable(t *testing.T) { // 压缩归档 + 当前未压缩文件一起统计，必须一条不漏 content := readAllGz(t, dir) + readAllLogs(t, dir) - if !strings.Contains(content, "[info]{") { - t.Errorf("内容不像日志: %.120q", content) + // 落到磁盘的每条记录都应是合法 JSON 行（便于采集端解析） + if !jsonLinesValid(t, content) { + t.Errorf("归档内容不是合法 JSON 行: %.160q", content) } missing := 0 for i := 0; i < n; i++ { @@ -274,6 +276,31 @@ func TestSizeSplitOnRestart(t *testing.T) { } } +// jsonLinesValid 校验每行都是合法 JSON（空行忽略） +func jsonLinesValid(t *testing.T, content string) bool { + t.Helper() + lines := strings.Split(strings.TrimSpace(content), "\n") + if len(lines) == 0 { + return false + } + for i, line := range lines { + line = strings.TrimSpace(line) + if line == "" { + continue + } + var v map[string]any + if err := json.Unmarshal([]byte(line), &v); err != nil { + t.Logf("第 %d 行不是合法 JSON: %v\n%s", i+1, err, line) + return false + } + if v["level"] == nil { + t.Logf("第 %d 行缺少 level 字段: %s", i+1, line) + return false + } + } + return true +} + // readAllGz 解开目录下所有 .gz 归档 func readAllGz(t *testing.T, dir string) string { t.Helper() diff --git a/loggerx_format_test.go b/loggerx_format_test.go new file mode 100644 index 0000000..01bed4b --- /dev/null +++ b/loggerx_format_test.go @@ -0,0 +1,187 @@ +package loggerx_test + +import ( + "context" + "encoding/json" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/yuninks/loggerx" +) + +func readOne(t *testing.T, dir, file string) string { + t.Helper() + files, _ := filepath.Glob(filepath.Join(dir, "*_"+file)) + if len(files) == 0 { + files, _ = filepath.Glob(filepath.Join(dir, file)) + } + if len(files) == 0 { + t.Fatalf("没找到 %s", file) + } + b, err := os.ReadFile(files[0]) + if err != nil { + t.Fatal(err) + } + return string(b) +} + +// 默认（不调用 SetFormat）必须是合法 JSON —— 与 readme 的承诺一致 +func TestDefaultFormatIsJSON(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), loggerx.SetDir(dir)) + l.Info(context.Background(), "hello") + if err := l.Close(); err != nil { + t.Fatal(err) + } + + line := strings.TrimSpace(readOne(t, dir, "info.log")) + var v map[string]any + if err := json.Unmarshal([]byte(line), &v); err != nil { + t.Fatalf("默认格式不是合法 JSON: %v\n%s", err, line) + } + if v["level"] != "info" { + t.Errorf("level=%v", v["level"]) + } +} + +// SetFormat(FormatText) 之后输出单行文本，且仍是一行一条 +func TestTextFormat(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetFormat(loggerx.FormatText), + ) + ctx := context.Background() + l.Info(ctx, "hello text") + l.Errorf(ctx, "boom %d", 42) + if err := l.Close(); err != nil { + t.Fatal(err) + } + + info := strings.TrimSpace(readOne(t, dir, "info.log")) + if info == "" { + t.Fatal("text 格式没有输出") + } + for _, want := range []string{"level=info", "time=", "file=", "content="} { + if !strings.Contains(info, want) { + t.Errorf("text 输出缺少 %q: %s", want, info) + } + } + if strings.HasPrefix(info, "{") { + t.Errorf("SetFormat(text) 之后不应还是 JSON: %s", info) + } + if strings.Count(info, "\n") != 0 { + t.Errorf("一条日志必须占一行: %q", info) + } + + errLine := strings.TrimSpace(readOne(t, dir, "error.log")) + if !strings.Contains(errLine, "level=error") || !strings.Contains(errLine, "42") { + t.Errorf("error 的 text 输出不正确: %s", errLine) + } +} + +// 内容里有空格/引号时，text 格式用引号包起来，避免歧义 +func TestTextFormatQuotesAmbiguousValues(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetFormat(loggerx.FormatText), + ) + l.Info(context.Background(), "has space and \"quote\"") + if err := l.Close(); err != nil { + t.Fatal(err) + } + line := strings.TrimSpace(readOne(t, dir, "info.log")) + if !strings.Contains(line, `content="`) { + t.Errorf("含空格/引号的值应当被引号包裹: %s", line) + } +} + +// SetFormat 传非法值时应保持默认，而不是切到一个没实现的格式 +func TestInvalidFormatKeepsDefault(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetFormat(loggerx.Format("yaml")), + ) + l.Info(context.Background(), "still-json") + if err := l.Close(); err != nil { + t.Fatal(err) + } + line := strings.TrimSpace(readOne(t, dir, "info.log")) + var v map[string]any + if err := json.Unmarshal([]byte(line), &v); err != nil { + t.Errorf("非法格式值不该改变默认行为: %v\n%s", err, line) + } +} + +// SetPrefix 必须真的加上前缀（两种格式都生效） +func TestPrefixApplied(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetPrefix("[order-svc] "), + ) + l.Info(context.Background(), "with-prefix") + if err := l.Close(); err != nil { + t.Fatal(err) + } + line := readOne(t, dir, "info.log") + if !strings.HasPrefix(line, "[order-svc] ") { + t.Errorf("前缀未生效: %q", line) + } + // 前缀之后仍然要是合法 JSON + body := strings.TrimSpace(strings.TrimPrefix(line, "[order-svc] ")) + var v map[string]any + if err := json.Unmarshal([]byte(body), &v); err != nil { + t.Errorf("前缀后的内容不是合法 JSON: %v\n%s", err, body) + } +} + +// text 格式 + 前缀 + expandData 组合 +func TestTextFormatWithPrefixAndExpand(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetFormat(loggerx.FormatText), + loggerx.SetPrefix("P|"), + loggerx.SetExpandData("app", "order"), + ) + l.Info(context.Background(), "combo") + if err := l.Close(); err != nil { + t.Fatal(err) + } + line := strings.TrimSpace(readOne(t, dir, "info.log")) + if !strings.HasPrefix(line, "P|level=info") { + t.Errorf("前缀/格式组合输出不正确: %s", line) + } + if !strings.Contains(line, "app=order") { + t.Errorf("expandData 未出现在 text 输出里: %s", line) + } +} + +// text 格式下不可序列化的内容也不能丢 +func TestTextFormatUnmarshalableContent(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetFormat(loggerx.FormatText), + ) + l.Info(context.Background(), make(chan int), func() {}) + l.Info(context.Background(), "after") + if err := l.Close(); err != nil { + t.Fatal(err) + } + content := readOne(t, dir, "info.log") + lines := strings.Split(strings.TrimSpace(content), "\n") + if len(lines) != 2 { + t.Fatalf("期望 2 行，实际 %d: %q", len(lines), content) + } + for i, line := range lines { + if !strings.Contains(line, "content=") { + t.Errorf("第 %d 行缺少 content: %s", i+1, line) + } + } +} diff --git a/loggerx_globalstate_test.go b/loggerx_globalstate_test.go new file mode 100644 index 0000000..c84ca7b --- /dev/null +++ b/loggerx_globalstate_test.go @@ -0,0 +1,102 @@ +package loggerx_test + +import ( + "context" + "log" + "os" + "path/filepath" + "testing" + + "github.com/yuninks/loggerx" +) + +// 全局 log 默认不被接管：NewLogger 不该静默改变宿主的全局状态 +func TestNoGlobalHijackByDefault(t *testing.T) { + before := log.Writer() + + l := loggerx.NewLogger(context.Background(), loggerx.SetDir(t.TempDir())) + defer l.Close() + + if got := log.Writer(); got != before { + t.Errorf("默认不该接管全局 log，但现在 log.Writer 变了: %T", got) + } + _ = l +} + +// TestGlobalLogTakeoverAndRestore 显式 SetAsGlobalLog 才接管；Close 必须还原成最初的 writer +func TestGlobalLogTakeoverAndRestore(t *testing.T) { + // 全局 log 是进程级状态，先存后恢复，避免污染同包其它测试 + original := log.Writer() + t.Cleanup(func() { log.SetOutput(original) }) + + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(t.TempDir()), + loggerx.SetAsGlobalLog(), + ) + if got, ok := log.Writer().(*loggerx.Logger); !ok || got != l { + t.Fatalf("SetAsGlobalLog 之后 log.Writer 应是该实例，实际 %T", log.Writer()) + } + + if err := l.Close(); err != nil { + t.Fatalf("Close: %v", err) + } + // Close 会还原成「纪录下来的最初 writer」。 + // 若本进程此前已被别的实例接管过（测试场景常见），还原目标不是此刻的 original， + // 所以这里只断言「不再是已关闭的实例」，再断言它可写 + if got, ok := log.Writer().(*loggerx.Logger); ok && got == l { + t.Errorf("Close 之后全局 log 仍指向已关闭的实例，后续 stdlib 日志会被静默丢弃") + } + log.Println("after-restore-probe") +} + +// TestGlobalLogRestoresOriginalAfterTwoInstances 两个实例先后接管再关闭： +// 全局 log 不能停在「已关闭的实例」上，否则后续 stdlib 日志被静默丢弃 +func TestGlobalLogRestoresOriginalAfterTwoInstances(t *testing.T) { + original := log.Writer() + t.Cleanup(func() { log.SetOutput(original) }) + + l1 := loggerx.NewLogger(context.Background(), loggerx.SetDir(t.TempDir()), loggerx.SetAsGlobalLog()) + l2 := loggerx.NewLogger(context.Background(), loggerx.SetDir(t.TempDir()), loggerx.SetAsGlobalLog()) + + // l2 是当前持有者 + if got, ok := log.Writer().(*loggerx.Logger); !ok || got != l2 { + t.Fatal("后接管的实例应该是当前持有者") + } + + if err := l2.Close(); err != nil { + t.Fatalf("l2.Close: %v", err) + } + if err := l1.Close(); err != nil { + t.Fatalf("l1.Close: %v", err) + } + + // 关键不变式：全局 log 必须是「可用的 writer」，绝不能是已关闭的 Logger + if got, ok := log.Writer().(*loggerx.Logger); ok { + t.Errorf("两次接管并关闭后全局 log 仍指向 Logger(%p)，后续 stdlib 日志会被丢弃", got) + } + log.Println("after-restore") +} + +// 关闭之后 stdlib log 不能继续写进已关闭的实例 +func TestNoHijackAfterClose(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), loggerx.SetDir(dir), loggerx.SetAsGlobalLog()) + if err := l.Close(); err != nil { + t.Fatalf("Close: %v", err) + } + + // 直接对已关闭实例写入必须返回 ErrClosed（供调用方判断） + if _, err := l.Write([]byte("x")); err == nil { + t.Error("对已关闭实例写入应返回错误") + } else if err != loggerx.ErrClosed { + t.Logf("对已关闭实例写入返回: %v", err) + } + + // 文件句柄应已全部释放（Windows 下能删掉才算真的关了） + files, _ := filepath.Glob(filepath.Join(dir, "*.log")) + for _, f := range files { + if err := os.Remove(f); err != nil { + t.Errorf("Close 后仍无法删除 %s: %v", filepath.Base(f), err) + } + } +} diff --git a/loggerx_prod_gaps_test.go b/loggerx_prod_gaps_test.go new file mode 100644 index 0000000..e7b5fca --- /dev/null +++ b/loggerx_prod_gaps_test.go @@ -0,0 +1,188 @@ +package loggerx_test + +import ( + "context" + "encoding/json" + "errors" + "os" + "path/filepath" + "strings" + "sync" + "testing" + + "github.com/yuninks/loggerx" +) + +// 级别过滤：设为 Info 之后 Debug 必须一条都不落盘 +func TestMinLevelFiltersDebug(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetMinLevel(loggerx.LevelInfo), + ) + l.Debug(context.Background(), "NOISY-DEBUG") + l.Info(context.Background(), "KEEP-INFO") + if err := l.Close(); err != nil { + t.Fatalf("Close: %v", err) + } + + content := readAllLogs(t, dir) + if strings.Contains(content, "NOISY-DEBUG") { + t.Error("SetMinLevel(LevelInfo) 未生效：Debug 仍然落盘") + } + if !strings.Contains(content, "KEEP-INFO") { + t.Error("Info 被错误过滤掉了") + } +} + +// LevelOff 之后什么都不写 +func TestMinLevelOff(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetMinLevel(loggerx.LevelOff), + ) + l.Error(context.Background(), "SHOULD-NOT-APPEAR") + if err := l.Close(); err != nil { + t.Fatal(err) + } + if content := readAllLogs(t, dir); strings.Contains(content, "SHOULD-NOT-APPEAR") { + t.Errorf("LevelOff 之后仍有日志落盘: %s", content) + } +} + +// 落盘格式必须是合法 JSON 行，且带 level 字段（便于采集端解析） +// 注意：不同级别分文件存放（info.log / error.log），所以按文件分别断言 +func TestOutputIsValidJSONLines(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), loggerx.SetDir(dir)) + ctx := context.Background() + l.Info(ctx, "info-msg") + l.Warn(ctx, "warn-msg") + l.Error(ctx, "err-msg") + if err := l.Close(); err != nil { + t.Fatal(err) + } + + check := func(file, wantLevel string) { + t.Helper() + files, _ := filepath.Glob(filepath.Join(dir, "*_"+file)) + if len(files) == 0 { + t.Fatalf("没有找到 %s", file) + } + b, err := os.ReadFile(files[0]) + if err != nil { + t.Fatal(err) + } + lines := strings.Split(strings.TrimSpace(string(b)), "\n") + if len(lines) != 1 { + t.Fatalf("%s 期望 1 行，实际 %d 行: %q", file, len(lines), string(b)) + } + var v map[string]any + if err := json.Unmarshal([]byte(lines[0]), &v); err != nil { + t.Fatalf("%s 不是合法 JSON: %v\n%s", file, err, lines[0]) + } + if v["level"] != wantLevel { + t.Errorf("%s 的 level=%v，期望 %v", file, v["level"], wantLevel) + } + if _, ok := v["time"]; !ok { + t.Errorf("%s 缺少 time 字段", file) + } + if _, ok := v["content"]; !ok { + t.Errorf("%s 缺少 content 字段", file) + } + } + check("info.log", "info") + check("warn.log", "warn") + check("error.log", "error") +} + +// readAllLogsRecursive 递归读取目录下所有日志（含 channel 子目录） +func readAllLogsRecursive(t *testing.T, dir string) string { + t.Helper() + var sb strings.Builder + _ = filepath.Walk(dir, func(p string, info os.FileInfo, err error) error { + if err != nil || info.IsDir() { + return nil + } + b, rerr := os.ReadFile(p) + if rerr != nil { + t.Fatalf("读取 %s: %v", p, rerr) + } + sb.Write(b) + return nil + }) + return sb.String() +} + +// SetErrorHandler 必须能拿到内部错误 +func TestErrorHandlerReceivesErrors(t *testing.T) { + boom := errors.New("driver boom") + var mu sync.Mutex + var got []error + + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(t.TempDir()), + loggerx.SetPrintFile(false), + loggerx.SetErrorHandler(func(err error) { + mu.Lock() + got = append(got, err) + mu.Unlock() + }), + loggerx.SetExtraDriver(writerFunc(func(p []byte) (int, error) { + return 0, boom + })), + ) + l.Info(context.Background(), "trigger") + if err := l.Close(); err != nil { + t.Fatalf("Close: %v", err) + } + + mu.Lock() + defer mu.Unlock() + if len(got) == 0 { + t.Fatal("驱动写失败没有通过 SetErrorHandler 上报，运维完全看不到") + } + if !errors.Is(got[0], boom) { + t.Errorf("错误内容不符合预期: %v", got[0]) + } +} + +// 关闭后再写应能被 errors.Is(err, ErrClosed) 判断出来 +func TestErrClosedIsDiscoverable(t *testing.T) { + l := loggerx.NewLogger(context.Background(), loggerx.SetDir(t.TempDir())) + if err := l.Close(); err != nil { + t.Fatal(err) + } + _, err := l.Write([]byte("x")) + if !errors.Is(err, loggerx.ErrClosed) { + t.Errorf("期望 errors.Is(err, ErrClosed)，实际: %v", err) + } +} + +// channel 名来自外部输入时不能逃出日志目录 +func TestChannelNameCannotEscapeDir(t *testing.T) { + base := t.TempDir() + dir := filepath.Join(base, "logs") + l := loggerx.NewLogger(context.Background(), loggerx.SetDir(dir)) + + // 试图用 ../ 写到日志目录外面 + l.Channel("../../evil").Info(context.Background(), "ESCAPE-ATTEMPT") + if err := l.Close(); err != nil { + t.Fatal(err) + } + + // 日志目录之外不应出现任何我们写的文件 + entries, err := os.ReadDir(base) + if err != nil { + t.Fatal(err) + } + for _, e := range entries { + if e.Name() != "logs" { + t.Errorf("channel 名逃出了日志目录，产生了 %s", e.Name()) + } + } + if !strings.Contains(readAllLogsRecursive(t, dir), "ESCAPE-ATTEMPT") { + t.Error("清洗后的 channel 名仍然应该把日志写进日志目录（不能丢日志）") + } +} diff --git a/loggerx_wedge_test.go b/loggerx_wedge_test.go new file mode 100644 index 0000000..7f554e0 --- /dev/null +++ b/loggerx_wedge_test.go @@ -0,0 +1,109 @@ +package loggerx_test + +import ( + "context" + "errors" + "log" + "strings" + "sync" + "testing" + "time" + + "github.com/yuninks/loggerx" +) + +// F1 验证：异步消费路径里 panic 之后，整个日志系统是否彻底卡死 +func TestPanicInAsyncConsumerWedgesLogger(t *testing.T) { + dir := t.TempDir() + + // 一个会 panic 的 driver（模拟用户 writer / gin writer 里出问题） + var once sync.Once + boom := writerFunc(func(p []byte) (int, error) { + once.Do(func() { panic("driver exploded") }) + return len(p), nil + }) + + l := loggerx.NewLogger(context.Background(), + loggerx.SetDir(dir), + loggerx.SetPrintFile(false), + loggerx.SetExtraDriver(boom), + loggerx.SetWriteAsync(), + ) + + // 第一条触发 panic（消费协程挂掉） + l.Info(context.Background(), "trigger") + + // 之后继续写，看是否会在队列满之前就卡死 + done := make(chan struct{}) + go func() { + defer close(done) + for i := 0; i < 3000; i++ { + l.Info(context.Background(), "after-panic") + } + }() + + select { + case <-done: + t.Log("panic 之后仍能继续写入（未卡死）") + case <-time.After(5 * time.Second): + t.Fatal("F1 复现：异步消费协程 panic 后，写入方永久阻塞（队列满后死锁）") + } + + // Close 是否会卡死 + closed := make(chan error, 1) + go func() { closed <- l.Close() }() + select { + case err := <-closed: + t.Logf("Close 返回: %v", err) + case <-time.After(10 * time.Second): + t.Fatal("F1 复现：Close 永久阻塞在 wg.Wait()") + } +} + +// F7 验证：经 stdlib log 写入时，异步队列是否保留了 log 包会复用的缓冲 +func TestStdLogBufferReuseInAsync(t *testing.T) { + dir := t.TempDir() + l := loggerx.NewLogger(context.Background(), loggerx.SetDir(dir), loggerx.SetWriteAsync()) + defer l.Close() + + log.SetOutput(l) + // stdlib log 用 sync.Pool 的缓冲，Write 返回后立即归还并复用 + for i := 0; i < 2000; i++ { + log.Printf("POOL-%05d-%s", i, string(make([]byte, 200))) + } + + if err := l.Close(); err != nil { + t.Fatalf("Close: %v", err) + } + + // 逐条检查：每个 POOL-nnnnn 是否都完整（不再被复用的池缓冲破坏） + content := readAllLogs(t, dir) + bad := 0 + for i := 0; i < 2000; i++ { + if !strings.Contains(content, "POOL-"+pad(i)) { + bad++ + } + } + if bad > 0 { + t.Errorf("F7 复现：%d / 2000 条日志内容缺失或被复用缓冲破坏", bad) + } +} + +func pad(i int) string { + s := "00000" + d := "" + for i > 0 { + d = string(rune('0'+i%10)) + d + i /= 10 + } + if len(d) >= len(s) { + return d + } + return s[:len(s)-len(d)] + d +} + +type writerFunc func([]byte) (int, error) + +func (f writerFunc) Write(p []byte) (int, error) { return f(p) } + +var errBoom = errors.New("boom") diff --git a/middleware/traceId.go b/middleware/traceId.go index 5936010..cf8b8a5 100644 --- a/middleware/traceId.go +++ b/middleware/traceId.go @@ -4,45 +4,91 @@ import ( "context" "github.com/gin-gonic/gin" - uuid "github.com/satori/go.uuid" + "github.com/google/uuid" "github.com/yuninks/loggerx" ) -// 设置普通的traceId -func SetTraceIdByKey(ctx context.Context, traceKey string) context.Context { - if traceKey == "" { - traceKey = "trace_id" - } +// traceCtxKey 是放在 context 里的 trace id 的键类型 +// +// 刻意用自定义类型而不是裸 string：go vet 会直接报 SA1029， +// 而且裸 string 作 key 有和第三方库撞键的风险 +type traceCtxKey struct{ field string } - val := ctx.Value(traceKey) - if val == nil { - ctx = context.WithValue(ctx, traceKey, uuid.NewV4().String()) - } - return ctx -} +// TraceHeader 默认的 trace 请求头/响应头名字 +const TraceHeader = "X-Trace-Id" -// 设置logger的traceId +// SetTraceId 给 ctx 打上 logger 需要的 trace id，返回带值的 ctx +// 已经存在时不覆盖，保证同一个请求内链路一致 func SetTraceId(ctx context.Context, logger *loggerx.Logger) context.Context { return SetTraceIdByKey(ctx, logger.GetTraceField()) } -// 设置Gin的traceId -func SetGinTraceIdByKey(traceKey string) gin.HandlerFunc { +// SetTraceIdByKey 按指定字段名给 ctx 打 trace id +// traceKey 为空时用 "trace_id" +func SetTraceIdByKey(ctx context.Context, traceKey string) context.Context { + if traceKey == "" { + traceKey = "trace_id" + } + if ctx == nil { + ctx = context.Background() + } + if v, _ := ctx.Value(traceCtxKey{traceKey}).(string); v != "" { + return ctx + } + return context.WithValue(ctx, traceCtxKey{traceKey}, uuid.NewString()) +} +// GetTraceId 从 ctx 里取 trace id（取不到返回空串） +func GetTraceId(ctx context.Context, traceKey string) string { + if traceKey == "" { + traceKey = "trace_id" + } + if ctx == nil { + return "" + } + v, _ := ctx.Value(traceCtxKey{traceKey}).(string) + return v +} + +// SetGinTraceId 生成/透传 trace id 的 Gin 中间件 +// +// 行为： +// - 优先取请求头 X-Trace-Id（方便上游透传，跨服务串起同一条链路） +// - 没有就生成一个 +// - 写回响应头，下游/客户端能拿到同一个 id，便于排障 +// - 同时写进 gin.Context（日志里能取到）与 request context +func SetGinTraceId(logger *loggerx.Logger) gin.HandlerFunc { + return SetGinTraceIdByKey(logger.GetTraceField(), TraceHeader) +} + +// SetGinTraceIdByKey 与 SetGinTraceId 相同，但可自定义字段名 +// header 为空表示不读也不写请求/响应头 +func SetGinTraceIdByKey(traceKey, header string) gin.HandlerFunc { if traceKey == "" { traceKey = "trace_id" } - return func(ctx *gin.Context) { - traceId := ctx.Request.Header.Get(traceKey) - if traceId == "" { - traceId = uuid.NewV4().String() + return func(c *gin.Context) { + var traceId string + if header != "" { + traceId = c.Request.Header.Get(header) } - ctx.Set(traceKey, traceId) + if traceId == "" { + traceId = uuid.NewString() + } + + c.Set(traceKey, traceId) + ctx := context.WithValue(c.Request.Context(), traceCtxKey{traceKey}, traceId) + c.Request = c.Request.WithContext(ctx) + + if header != "" { + c.Writer.Header().Set(header, traceId) + } + c.Next() } } -// 设置Gin的traceId +// SetGinTraceIdByLogger 兼容旧名字：用 logger 的 trace 字段名生成中间件 func SetGinTraceIdByLogger(logger *loggerx.Logger) gin.HandlerFunc { - return SetGinTraceIdByKey(logger.GetTraceField()) + return SetGinTraceId(logger) } diff --git a/middleware/traceId_test.go b/middleware/traceId_test.go new file mode 100644 index 0000000..b56625e --- /dev/null +++ b/middleware/traceId_test.go @@ -0,0 +1,154 @@ +package middleware_test + +import ( + "context" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "testing" + + "github.com/gin-gonic/gin" + "github.com/google/uuid" + "github.com/yuninks/loggerx" + "github.com/yuninks/loggerx/middleware" +) + +func newTestEngine(log *loggerx.Logger) *gin.Engine { + gin.SetMode(gin.TestMode) + g := gin.New() + g.Use(middleware.SetGinTraceId(log)) + return g +} + +// trace id 应当写回响应头，并在 handler 里可读 +func TestGinTraceIdSetsResponseHeader(t *testing.T) { + log := loggerx.NewLogger(context.Background(), loggerx.SetDir(t.TempDir())) + defer log.Close() + + var seen string + g := newTestEngine(log) + g.GET("/ping", func(c *gin.Context) { + seen = middleware.GetTraceId(c.Request.Context(), log.GetTraceField()) + c.Status(200) + }) + + w := httptest.NewRecorder() + g.ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/ping", nil)) + + header := w.Header().Get(middleware.TraceHeader) + if header == "" { + t.Fatalf("响应头 %s 没有写回，跨服务排障拿不到同一个 id", middleware.TraceHeader) + } + if _, err := uuid.Parse(header); err != nil { + t.Errorf("生成的 trace id 不是合法 uuid: %q", header) + } + if seen != header { + t.Errorf("handler 里读到的 trace id (%q) 与响应头 (%q) 不一致", seen, header) + } +} + +// 上游带 trace id 时必须透传，不能重新生成 +func TestGinTraceIdPropagatesFromHeader(t *testing.T) { + log := loggerx.NewLogger(context.Background(), loggerx.SetDir(t.TempDir())) + defer log.Close() + + const upstream = "8f3d1c22-1111-4222-8333-444455556666" + var seen string + g := newTestEngine(log) + g.GET("/ping", func(c *gin.Context) { + seen = middleware.GetTraceId(c.Request.Context(), log.GetTraceField()) + c.Status(200) + }) + + req := httptest.NewRequest(http.MethodGet, "/ping", nil) + req.Header.Set(middleware.TraceHeader, upstream) + w := httptest.NewRecorder() + g.ServeHTTP(w, req) + + if seen != upstream { + t.Errorf("上游 trace id 未透传: 期望 %q 实际 %q", upstream, seen) + } + if got := w.Header().Get(middleware.TraceHeader); got != upstream { + t.Errorf("响应头应回传上游 trace id，实际 %q", got) + } +} + +// 日志里应当带上 middleware 注入的 trace id（gin.Context 与 request ctx 两条路径） +func TestTraceIdAppearsInLog(t *testing.T) { + dir := t.TempDir() + log := loggerx.NewLogger(context.Background(), loggerx.SetDir(dir)) + defer log.Close() + + g := newTestEngine(log) + g.GET("/ping", func(c *gin.Context) { + log.Info(c, "via-gin-ctx") + log.Info(c.Request.Context(), "via-request-ctx") + c.Status(200) + }) + + w := httptest.NewRecorder() + g.ServeHTTP(w, httptest.NewRequest(http.MethodGet, "/ping", nil)) + traceId := w.Header().Get(middleware.TraceHeader) + if traceId == "" { + t.Fatal("没有 trace id") + } + if err := log.MustSync(); err != nil { + t.Fatal(err) + } + + content := readAll(t, dir) + if !contains(content, traceId) { + t.Errorf("日志里没有出现 trace id %q:\n%s", traceId, content) + } + if !contains(content, "via-gin-ctx") || !contains(content, "via-request-ctx") { + t.Errorf("两条日志都应当写入:\n%s", content) + } +} + +// SetTraceId 打标：已存在时不覆盖，取不到时返回空串而不是 panic +func TestSetTraceIdByKeySemantics(t *testing.T) { + log := loggerx.NewLogger(context.Background(), loggerx.SetDir(t.TempDir())) + defer log.Close() + + ctx := middleware.SetTraceId(context.Background(), log) + first := middleware.GetTraceId(ctx, log.GetTraceField()) + if first == "" { + t.Fatal("SetTraceId 应当生成一个 id") + } + + again := middleware.SetTraceId(ctx, log) + if got := middleware.GetTraceId(again, log.GetTraceField()); got != first { + t.Errorf("已有 trace id 时不该覆盖: %q -> %q", first, got) + } + + if got := middleware.GetTraceId(nil, "trace_id"); got != "" { + t.Errorf("nil ctx 应返回空串，实际 %q", got) + } + if got := middleware.GetTraceId(context.Background(), "trace_id"); got != "" { + t.Errorf("没有值时该返回空串，实际 %q", got) + } +} + +func readAll(t *testing.T, dir string) string { + t.Helper() + var sb []byte + files, _ := filepath.Glob(filepath.Join(dir, "*.log")) + for _, f := range files { + b, err := os.ReadFile(f) + if err != nil { + t.Fatalf("读取 %s: %v", f, err) + } + sb = append(sb, b...) + } + return string(sb) +} + +func contains(s, sub string) bool { + for i := 0; i+len(sub) <= len(s); i++ { + if s[i:i+len(sub)] == sub { + return true + } + } + return false +} diff --git a/options.go b/options.go index 6553cc0..3a649a5 100644 --- a/options.go +++ b/options.go @@ -9,11 +9,12 @@ import ( type loggerOption struct { prefix string // 日志前缀 - format string // text json + format Format // json / text dir string // 文件目录 isGinLog bool isGid bool isPrintFile bool + asGlobalLog bool // 是否接管全局 stdlib log（默认 false） writeType writeType // 是否异步罗盘 traceField string // trace字段 errorToInfo bool // 错误日志是否写入info日志 @@ -24,6 +25,8 @@ type loggerOption struct { compress bool // 归档文件是否压缩为 .gz compressLvl int // gzip 压缩级别 flushEvery time.Duration // 定时刷盘间隔，0 表示不开启 + minLevel Level // 最低输出级别 + onError func(error) // 内部错误回调 timeZone *time.Location // 时区 escapeHTML bool expandData map[string]string // 扩展字段 @@ -40,11 +43,11 @@ const ( func defaultOptions() loggerOption { return loggerOption{ - isGinLog: true, + isGinLog: false, // 默认不接管 gin 写手：非 Gin 服务不该被改全局状态 isGid: true, isPrintFile: true, writeType: writeTypeDefault, // 默认同步 - format: "json", + format: FormatJSON, dir: "./log", traceField: "trace_id", days: 7, @@ -99,17 +102,31 @@ func SetErrorToInfo() Option { } } -// 日志的前缀 +// 日志前缀 +// 会加在每行日志最前面（JSON 与 text 都生效），便于多实例共用一个目录时区分来源 func SetPrefix(prefix string) Option { return func(o *loggerOption) { o.prefix = prefix } } -// 日志格式(默认json) -func SetFormat(format string) Option { +// 输出格式 +type Format string + +const ( + // FormatJSON 每行一条 JSON（默认，推荐给采集端） + FormatJSON Format = "json" + // FormatText 每行一条紧凑文本，适合人直接看 + FormatText Format = "text" +) + +// 日志格式（默认 FormatJSON） +// 传非法值时保持原值，不会静默切到别的格式 +func SetFormat(format Format) Option { return func(o *loggerOption) { - o.format = format + if format == FormatJSON || format == FormatText { + o.format = format + } } } @@ -127,6 +144,78 @@ func SetGinLog(open bool) Option { } } +// 日志级别。级别低于设定值的日志会被直接丢弃，不落盘 +type Level uint8 + +const ( + LevelDebug Level = iota + LevelInfo + LevelWarn + LevelError + // LevelOff 关闭所有级别（连 error 也不写） + LevelOff +) + +// String 便于打印 +func (lv Level) String() string { + switch lv { + case LevelDebug: + return "debug" + case LevelInfo: + return "info" + case LevelWarn: + return "warn" + case LevelError: + return "error" + case LevelOff: + return "off" + default: + return "unknown" + } +} + +// SetMinLevel 设置最低输出级别（默认 LevelDebug，即全部输出） +// +// 生产环境通常设成 LevelInfo：这样代码里的 Debug 调用不会白算一遍 +// JSON、也不会落盘占空间 +func SetMinLevel(lv Level) Option { + return func(o *loggerOption) { + o.minLevel = lv + } +} + +// SetErrorHandler 注册内部错误处理回调（默认 nil） +// +// 用于把「日志库自身的故障」暴露给运维：磁盘满、句柄失效、归档压缩失败、 +// 定时刷盘失败等。不注册时这些错误只体现在返回值里，而调用方通常忽略返回值， +// 问题就完全不可见了。 +// +// 建议接到告警通道或一个「不会失败」的输出（例如 stderr）： +// +// loggerx.NewLogger(ctx, loggerx.SetErrorHandler(func(err error) { +// fmt.Fprintln(os.Stderr, "loggerx:", err) +// })) +// +// 回调在写日志的调用栈上同步执行，务必保持轻量， +// 且不要在里面再调用本实例的日志方法（可能递归） +func SetErrorHandler(fn func(error)) Option { + return func(o *loggerOption) { + o.onError = fn + } +} + +// 是否把全局标准库 log 的输出接管到本实例（默认 false，不接管） +// +// 默认不接管是刻意的：日志库在 import / NewLogger 时静默劫持宿主全局 log +// 会带来两个生产事故场景 —— 多个实例时后建的把先建的顶掉； +// Close 之后全局 log 仍指向已关闭实例，之后的日志被静默丢弃。 +// 确需接管（例如老代码大量使用 log.Printf）时再显式打开。 +func SetAsGlobalLog() Option { + return func(o *loggerOption) { + o.asGlobalLog = true + } +} + // 文件路径 func SetDir(dir string) Option { return func(o *loggerOption) { diff --git a/readme.md b/readme.md index c088e11..d1214bc 100644 --- a/readme.md +++ b/readme.md @@ -27,6 +27,10 @@ log := loggerx.NewLogger(ctx, loggerx.SetFlushInterval(200*time.Millisecond), // 定时刷盘，默认关闭 loggerx.SetEscapeHTML(false), // 是否转义 HTML，默认 true loggerx.SetGID(false), // 是否记录 goroutine id，默认 true + loggerx.SetFormat(loggerx.FormatJSON), // 输出格式：FormatJSON(默认) / FormatText + loggerx.SetPrefix("[order-svc] "), // 每行日志前缀，便于区分来源 + loggerx.SetMinLevel(loggerx.LevelInfo), // 最低输出级别，默认 LevelDebug(全输出) + loggerx.SetErrorHandler(onLogError), // 日志库自身故障回调（磁盘满/句柄失效等） loggerx.SetTraceField("trace_id"), // trace 字段名，默认 trace_id loggerx.SetErrorToInfo(), // error 是否同时写入 info 日志 loggerx.SetExpandData("app", "order"), // 每条日志追加固定字段 @@ -105,22 +109,85 @@ loggerx.SetWriteAsync() // 全局异步 ### Gin 中间件 ```go -g := gin.Default() log := loggerx.NewLogger(context.Background(), loggerx.SetToConsole()) defer log.Close() -g.Use(middleware.SetGinTraceIdByLogger(log)) // 读取/生成 trace_id -g.Use(middleware.SetGinParams(log)) // 记录请求与响应 +g := gin.New() +g.Use(gin.Recovery()) +g.Use(middleware.SetGinTraceId(log)) // 读取/生成 trace id，并写回响应头 X-Trace-Id +g.Use(middleware.SetGinParams(log)) // 记录请求与响应（含 body，截断到 1000 字节） + +g.GET("/ping", func(c *gin.Context) { + // trace id 同时注入 gin.Context 与 request context，两种写法日志里都能带上 + log.Info(c, "via gin ctx") + log.Info(c.Request.Context(), "via request ctx") + c.JSON(200, gin.H{"trace_id": middleware.GetTraceId(c.Request.Context(), log.GetTraceField())}) +}) ``` +trace id 的行为： + +- 优先取请求头 `X-Trace-Id`（上游透传，跨服务串起同一条链路），没有才生成 +- 生成后写回响应头，客户端/下游能拿到同一个 id +- 上下文里的 key 用自定义类型（不是裸 string），避免与第三方库撞键 +- 需要自定义头名时用 `middleware.SetGinTraceIdByKey("trace_id", "X-Request-Id")` + ### 与标准库 log 互通 -`NewLogger` 会把全局 `log` 的输出接管到该实例，同时继承 `io.Writer`，可以直接传给任何需要 `io.Writer` 的地方： +默认**不接管**全局 `log`（只 import 本包不会产生任何副作用）。 +需要把老代码里的 `log.Printf` 也收进日志文件时，显式打开： + +```go +log := loggerx.NewLogger(ctx, loggerx.SetDir("./log"), loggerx.SetAsGlobalLog()) +defer log.Close() // Close 会把全局 log 还原成接管前的 writer +``` + +`*Logger` 本身实现 `io.Writer`，也可以直接塞给任何需要 writer 的地方： ```go log.SetOutput(loggerx.NewLogger(ctx, loggerx.SetDir("./log"))) ``` +### 输出格式与前缀 + +```go +// JSON（默认）：每行一条合法 JSON，带 level 字段，推荐给采集端，也是性能最好的一种 +{"level":"info","time":"2026-09-13 14:07:39.731954","file":"/main.go:20","func":"main","gid":"7","content":["hello"]} + +// FormatText：单行紧凑文本，适合人直接看 +level=info time=2026-09-13 14:07:39.731954 file=/main.go:20 func=main gid=7 content=hello +``` + +两者都支持 `SetPrefix`，前缀加在行首（`[order-svc] level=info ...`）。 +text 格式下值里含空格/引号时会用 `%q` 包起来，保证一行一条且不歧义。 + +实测（本机 16 核）：默认 JSON 约 10.2 µs/条，text 约 12.1 µs/条。 +text 并非更快 —— 它走的是逐字段拼接，而 JSON 走的是已高度优化的 `encoding/json`。 +选 text 的理由是「人读着方便」，不是性能。 + +### 级别过滤 + +```go +loggerx.SetMinLevel(loggerx.LevelInfo) // 生产常用：Debug 直接丢弃，连 JSON 都不序列化 +loggerx.SetMinLevel(loggerx.LevelOff) // 全关 +``` + +### 把日志库自身的故障暴露出来 + +磁盘满、句柄失效、归档失败、刷盘超时这类问题默认只体现在返回值里，而调用方通常忽略返回值。 +注册回调后可以接到告警或一个「不会失败」的输出： + +```go +loggerx.NewLogger(ctx, + loggerx.SetDir("./log"), + loggerx.SetErrorHandler(func(err error) { + fmt.Fprintln(os.Stderr, "loggerx:", err) + }), +) +``` + +回调在写日志的调用栈上同步执行，务必保持轻量，且不要在里面再调用同一实例的日志方法。 + ## 落盘行为与保证 - **缓冲**：每条日志先写进 32KB 内存缓冲，写满才 `write` 一次系统调用。 @@ -157,7 +224,9 @@ log.SetOutput(loggerx.NewLogger(ctx, loggerx.SetDir("./log"))) 1. [X] 按照时间分割 2. [X] 按照文件大小分割（`SetSizeSplit`） 3. [ ] 按照日志行数分割 -6. [ ] 支持日志级别过滤（`SetFormat("text")` 尚未生效） +6. [X] 支持日志级别过滤（`SetMinLevel`） 7. [X] 异步落盘（按实例隔离，不再是全局队列） 8. [X] 支持是否转义 HTML 9. [X] 支持定时刷盘（`SetFlushInterval`） +10. [X] 支持 text / json 两种输出格式（`SetFormat`）与行前缀（`SetPrefix`） +11. [ ] 支持采样（高频日志降采样） diff --git a/remove.go b/remove.go index 300a343..315600a 100644 --- a/remove.go +++ b/remove.go @@ -4,6 +4,7 @@ import ( "fmt" "os" "path/filepath" + "strings" "time" ) @@ -25,10 +26,18 @@ func (l *Logger) delete() { }() // 先清掉「压缩完成但源文件没删掉」留下的冗余文件 if err := l.healCompressedLeftovers(); err != nil { - fmt.Println(err) + l.reportError(err) + } + // 清掉崩溃/被杀留下的半截压缩临时文件 + if err := l.sweepStaleTemps(); err != nil { + l.reportError(err) + } + // 释放长时间不活跃的句柄（通道名多变的场景会积累大量 fd + 32KB 缓冲） + if err := l.sweepIdleHandles(); err != nil { + l.reportError(err) } if err := l.walkAndDel(); err != nil { - fmt.Println(err) + l.reportError(err) } }() case <-l.ctx.Done(): @@ -46,11 +55,12 @@ func (l *Logger) walkAndDel() error { } deadline := time.Now().AddDate(0, 0, -l.option.days) + live := l.livePaths() err := filepath.Walk(l.option.dir, func(path string, info os.FileInfo, err error) error { if err != nil { // 单个文件出错不应该中断整个遍历 - fmt.Println(err) + l.reportError(err) return nil } @@ -68,19 +78,70 @@ func (l *Logger) walkAndDel() error { return nil } + // 绝不能删正在被本实例写入的文件： + // Linux 上删除已打开的文件会成功，之后所有写入都进了「已 unlink 的 inode」， + // 日志对外彻底不可见、空间也不释放；Windows 上则会一直删不掉刷报错 + if live[path] { + return nil + } + // 删除文件 / 空目录 if rerr := os.Remove(path); rerr != nil { - // 正被写入的文件在 Windows 上删不掉，等下一轮再试，不要终止遍历 - fmt.Println("删除文件失败", path, rerr) + // 正被外部进程占用的文件删不掉，等下一轮再试，不要终止遍历 + l.reportError(fmt.Errorf("loggerx: 删除文件失败 %s: %w", path, rerr)) return nil } - fmt.Println("删除文件", path) return nil }) return err } +// livePaths 当前所有打开着的日志文件路径集合 +func (l *Logger) livePaths() map[string]bool { + l.mu.RLock() + defer l.mu.RUnlock() + + live := make(map[string]bool, len(l.filePath)) + for _, f := range l.filePath { + if f != nil && f.fileName != "" { + live[f.fileName] = true + } + } + return live +} + +// staleTempAge 多久没动静的临时文件算垃圾 +const staleTempAge = time.Hour + +// sweepStaleTemps 清理崩溃/被杀时留下的半截压缩临时文件 +// +// gzipFile 只在自己的错误分支里删 .gz.tmp，进程被 SIGKILL 时来不及删， +// 而这些文件的扩展名既不是 .log 也不是 .gz，原来的清理逻辑完全看不到它们 +func (l *Logger) sweepStaleTemps() error { + cutoff := time.Now().Add(-staleTempAge) + + var errs []error + _ = filepath.Walk(l.option.dir, func(path string, info os.FileInfo, err error) error { + if err != nil || info.IsDir() { + return nil + } + if !strings.HasSuffix(path, gzipTempSuffix) { + return nil + } + // 留一点余量：可能正好有一个压缩任务在写它 + if info.ModTime().After(cutoff) { + return nil + } + if rerr := os.Remove(path); rerr != nil { + errs = append(errs, fmt.Errorf("loggerx: 清理半截压缩文件失败 %s: %w", path, rerr)) + return nil + } + return nil + }) + return joinErrors(errs) +} + // 判断空文件夹 func isEmptyDir(path string) bool { files, err := os.ReadDir(path) diff --git a/storage.go b/storage.go index 372b608..04e0215 100644 --- a/storage.go +++ b/storage.go @@ -1,8 +1,9 @@ package loggerx import ( + "errors" + "fmt" "io" - "log" "time" ) @@ -31,17 +32,23 @@ func (l *Logger) store(event string, b []byte) (n int, err error) { func (l *Logger) storeTo(channel, event string, b []byte) (n int, err error) { if l.option.isPrintFile { // 串行化写入：句柄缓冲区不是并发安全的， - // 异步消费协程与同步调用可能同时写同一个句柄 - l.writeMu.Lock() - n, err = l.storeFileTo(channel, event, b) - l.writeMu.Unlock() + // 异步消费协程与同步调用可能同时写同一个句柄。 + // 这里必须用 defer 解锁：一旦未来写入路径里出现 panic， + // 非 defer 的 Unlock 会被跳过，锁永久不释放，整个进程的日志全卡死 + n, err = func() (int, error) { + l.writeMu.Lock() + defer l.writeMu.Unlock() + return l.storeFileTo(channel, event, b) + }() if err != nil { return 0, err } } - // 驱动（控制台等）的写入失败不改变对调用方的契约 - _, _ = l.writeDrivers(b) + // 驱动（控制台等）的写入失败不改变对调用方的契约，但要上报 + if _, derr := l.writeDrivers(b); derr != nil { + l.reportError(fmt.Errorf("loggerx: 写入额外驱动失败: %w", derr)) + } return len(b), nil } @@ -88,11 +95,16 @@ func (l *Logger) storeFileTo(channel, event string, b []byte) (int, error) { } // rollFileTo 归档当前文件并返回新文件句柄 +// +// 任何失败路径都必须保证：filePath[key] 不会留下一个「已关闭」的句柄。 +// 否则后续写入只会进那个句柄的内存缓冲，而它已不在句柄表里， +// 刷新和关闭都遍历不到 —— 数据静默丢失且接口返回成功 func (l *Logger) rollFileTo(channel, event string, f *logFile) (*logFile, error) { key := fileKey{channel: channel, event: event} // 先把缓冲清空再关句柄，保证归档内容完整 if err := f.Close(); err != nil { + l.repairHandle(key, f) return nil, err } @@ -100,6 +112,7 @@ func (l *Logger) rollFileTo(channel, event string, f *logFile) (*logFile, error) // （按小时切割出来的名字本身就长这样：2026/09/13/06_info.log） path, err := l.archive(f.baseName, f.fileName) if err != nil { + l.repairHandle(key, f) return nil, err } @@ -112,6 +125,7 @@ func (l *Logger) rollFileTo(channel, event string, f *logFile) (*logFile, error) // 新文件带走递增序号，避免覆盖刚归档出去的同名文件 nf, err := l.openNumberedFile(key, l.nextIndex()) if err != nil { + l.repairHandle(key, nil) return nil, err } @@ -124,12 +138,60 @@ func (l *Logger) rollFileTo(channel, event string, f *logFile) (*logFile, error) return nf, nil } +// repairHandle 给某个 key 装回一个「可写」的句柄 +// +// 滚动失败时现场可能残留一个已关闭的句柄（还在表里或已被摘掉）， +// 这里统一替换成一个新打开的同名文件句柄，保证后续写入有地方落盘； +// 实在打不开就把表项摘掉，让下一次写入重新走完整的打开流程 +func (l *Logger) repairHandle(key fileKey, stale *logFile) { + l.mu.Lock() + if stale != nil { + if cur, ok := l.filePath[key]; ok && cur == stale { + delete(l.filePath, key) + } + } else { + delete(l.filePath, key) + } + l.mu.Unlock() + + nf, err := l.openNewFile(key) + if err != nil { + l.reportError(fmt.Errorf("loggerx: 滚动失败后无法重新打开日志文件 %s/%s: %w", key.channel, key.event, err)) + return + } + l.mu.Lock() + // 期间可能有别的 goroutine 已经装好了句柄，别覆盖 + if _, ok := l.filePath[key]; !ok { + l.filePath[key] = nf + } else { + _ = nf.Close() + } + l.mu.Unlock() +} + // 写入额外的驱动（控制台 / 自定义 writer） +// +// 用户传进来的 driver 往往是 *bytes.Buffer / *bufio.Writer 这类非并发安全的对象， +// 所以这里必须和文件写入一样串行化；同时逐个写、单个失败不影响其它 driver +// （io.MultiWriter 会在第一个错误处短路，把后面的输出一起吞掉） func (l *Logger) writeDrivers(b []byte) (int, error) { if len(l.option.drivers) == 0 { return 0, nil } - return io.MultiWriter(l.option.drivers...).Write(b) + + l.driverMu.Lock() + defer l.driverMu.Unlock() + + var errs []error + for _, d := range l.option.drivers { + if d == nil { + continue + } + if _, err := d.Write(b); err != nil { + errs = append(errs, err) + } + } + return len(b), joinErrors(errs) } // discardFile 关闭文件并从缓存中移除，使下次写入重新打开 @@ -190,22 +252,40 @@ func (l *Logger) toAsync(event string, b []byte) bool { defer l.async.end() // 必须在解锁之后 Done，保证 begin/end 覆盖整段投递 - ch <- cacheData{Channel: l.channel, Event: event, Data: b} + // 必须复制一份再入队：b 可能是标准库 log 从 sync.Pool 借来的行缓冲， + // io.Writer 契约明确禁止保留传入的切片 —— log 在 Write 返回后立刻把 + // 缓冲还池并复用，异步消费协程读到的就会是被改写的内存 + // （曾经导致 1374/2000 条日志内容错乱） + data := make([]byte, len(b)) + copy(data, b) + + ch <- cacheData{Channel: l.channel, Event: event, Data: data} return true } // asyncWorker 消费异步队列，直到队列被关闭 +// +// 关键：单条任务 panic 绝不能让消费循环退出。 +// 否则队列没人消费、channel 很快写满，之后所有写入方都会永久阻塞在 +// `ch <- ...` 上（应用整体卡死），Close 也会永远等不到 workerDone。 func (l *Logger) asyncWorker(q chan cacheData) { defer close(l.workerDone) + + for val := range q { + l.consumeOne(val) + } +} + +// consumeOne 处理一条异步任务，把 panic 限制在这一条之内 +func (l *Logger) consumeOne(val cacheData) { defer func() { if r := recover(); r != nil { - log.Println("loggerx: 异步写入协程异常:", r) + // 回调要包一层 recover：用户的错误处理函数自己也可能 panic + l.reportError(fmt.Errorf("loggerx: 异步写入单条日志时 panic: %v", r)) } }() - for val := range q { - // 按任务里记的 channel 落盘，避免多个 channel 的日志混到根目录 - _, _ = l.storeTo(val.Channel, val.Event, val.Data) - } + // 按任务里记的 channel 落盘，避免多个 channel 的日志混到根目录 + _, _ = l.storeTo(val.Channel, val.Event, val.Data) } // drainAsync 停止投递、关闭队列，并等消费协程把剩余任务全部写完 @@ -221,18 +301,33 @@ func (l *Logger) drainAsync() { return } - // 关键：必须等「已经进入投递临界区」的写入全部入队之后才能关队列。 - // 这里能看到 wg 已经是 0，就说明没有写入还卡在投递路径上， - // 否则 close(q) 之后它们再发就会 panic: send on closed channel + // 等「已进入投递临界区」的写入全部入队，之后才能关队列。 + // + // 这里刻意【不加超时】：wg 的非零计数正说明有 goroutine 卡在 + // 临界区里（通常是队列满导致 `ch <-` 阻塞）。若超时后就 close(q)， + // 那些还停在 `ch <-` 上的生产者会被唤醒并 panic: send on closed channel， + // 而它们跑在应用自己的 goroutine 上（Info/Write 的调用方）， + // 没有 recover，直接把进程打挂。 + // + // 不设超时也不会死等：只有消费者倒下才会让队列永久满， + // 而消费者现在对每条任务单独 recover（见 consumeOne），不会死。 l.async.wg.Wait() // 关闭队列并等消费者把缓冲里的任务全部处理完。 // 这一步必须真的等到 workerDone：否则 Close 会在消费协程还在写缓冲时 // 就刷盘并关闭文件，最后几条日志会连着句柄一起丢掉 close(q) + if !waitChanTimeout(l.workerDone, closeDrainTimeout) { + l.reportError(errors.New("loggerx: 等待异步日志落盘超时，队列中剩余日志可能丢失")) + } +} + +// waitChanTimeout 等通道关闭，超时返回 false +func waitChanTimeout(ch <-chan struct{}, d time.Duration) bool { select { - case <-l.workerDone: - case <-time.After(closeDrainTimeout): - log.Println("loggerx: 等待异步日志落盘超时") + case <-ch: + return true + case <-time.After(d): + return false } }