Post

PGO-Logger

Posted Updated
By Pancake Lee
10 min read
PGO-Logger

日志模块

我们希望得到怎么样的日志呢？

我们先看 zap 库最简单例子， 然后对比地提出我期望的日志格式， 最后我们看业务代码希望如何调用日志库。

zaplog

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

func TestZapLogger(t *testing.T) {
    logger, _ := zap.NewDevelopment()
    defer logger.Sync()
    logger.Debug("test zap Debug, 中文测试，1234567890")
    logger.Info("test zap Info, 中文测试，1234567890")
    logger.Warn("test zap Warn, 中文测试，1234567890")
    logger.Error("test zap Error, 中文测试，1234567890")

    log := logger.Sugar()
    log.Debug("test zap SugaredLogger Debug, 中文测试，1234567890")
    log.Debugf("test zap SugaredLogger Debug, 中文测试，%d", 1234567890)
    log.Debugln("test zap SugaredLogger Debugln, 中文测试，1234567890")
    log.Debugw("test zap SugaredLogger Debugw, 中文测试，1234567890",
        "key1", "value1", "key2", "value2")
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

2025-06-06T16:52:07.160+0800	DEBUG	logger/unit_test.go:13	test zap Debug, 中文测试，1234567890
2025-06-06T16:52:07.165+0800	INFO	logger/unit_test.go:14	test zap Info, 中文测试，1234567890
2025-06-06T16:52:07.166+0800	WARN	logger/unit_test.go:15	test zap Warn, 中文测试，1234567890
pgo/pkg/logger.TestZapLogger
	g:/workspace/pgo/pkg/logger/unit_test.go:15
testing.tRunner
	C:/Program Files/Go/src/testing/testing.go:1792
2025-06-06T16:52:07.166+0800	ERROR	logger/unit_test.go:16	test zap Error, 中文测试，1234567890
pgo/pkg/logger.TestZapLogger
	g:/workspace/pgo/pkg/logger/unit_test.go:16
testing.tRunner
	C:/Program Files/Go/src/testing/testing.go:1792
2025-06-06T16:52:07.166+0800	DEBUG	logger/unit_test.go:19	test zap SugaredLogger Debug, 中文测试，1234567890
2025-06-06T16:52:07.166+0800	DEBUG	logger/unit_test.go:20	test zap SugaredLogger Debug, 中文测试，1234567890
2025-06-06T16:52:07.166+0800	DEBUG	logger/unit_test.go:21	test zap SugaredLogger Debugln, 中文测试，1234567890
2025-06-06T16:52:07.166+0800	DEBUG	logger/unit_test.go:22	test zap SugaredLogger Debugw, 中文测试，1234567890	{"key1": "value1", "key2": "value2"}

期望

日志格式

首先，如果搭建了完善的日志平台，比如 ELK， 那么，这里对日志格式的微调没有太大意义，因为这些平台已经提供足够方便的功能查询日志。

只需要输出日志时，提供一份 key-value，录入足够多的索引到 ELK， 查询某个关键字，查询某个请求，查询某个用户的日志，都能得到很好的支持。

下面我们只讨论直接查阅日志文件的情况。 开发/运维服务器程序，不可避免的需要使用 cat/tail/vim 等查阅日志。

  • 期望：定长前缀 + Message + 变长后缀
  • 进阶：基础框架的定长前缀 + 业务框架的定长前缀 + Message + 业务框架的变长后缀 + 基础框架的变长后缀
1
2
3
4
5

250606T16:52:07.160 DEBUG test zap Debug, 中文测试，1234567890 aaa.go:13
250606T16:52:07.160 DEBUG test2 zap Debug, 中文测试2，1234567890 bbb.go:13

250606T16:52:07.160 DEBUG [RequestId] test zap Debug, 中文测试，1234567890 [有什么变长内容想要拼接呢] aaa.go:13
250606T16:52:07.160 DEBUG [RequestId] test2 zap Debug, 中文测试2，1234567890 [还没想好] bbb.go:13

文件命名

  • 期望：进程名 + 日期
    • test_20250606.log
  • 进阶 1：进程名 + PID + 日期
    • 每次重启都生成一个新的日志文件
    • 但这种方式会导致 zap 的日志轮转失效
  • 进阶 2：进程名 + 实例编号 + 日期
    • 适用于以多进程的方式运行多个实例
  • 另外：需要有软连接指向当前使用的日志文件

调用

首先，基础框架应该提供固定的日志初始化，业务代码只需要调用具体的输出方法 然后，业务框架应该封装一层，拼接上业务固定信息，比如所有日志都拼接上 RequestId，这样容易追踪同一个请求的所有日志

这里视乎项目是否有所谓的“业务框架”， 比如一个带有账号管理的系统，那么每个请求都应该带着 token 或者 session， 那么也许你会希望每条日志都输出当前的用户是谁，可以固定拼接用户名或者用户 ID。

logger 封装

基本方法

1
2
3
4
5

func InitLogger(isLogConsole bool, lv zapcore.Level, path string)
func Debug(args ...interface{})
func Debugf(template string, args ...interface{})

func LogErr(err error) error

1

250609 11:57:00.909	[D]	test logger Debug, 中文测试，1234567890 [unit_test.go:29]

耗时统计

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

func TestTimeLogger(t *testing.T) {
    InitLogger(true, zap.DebugLevel, "")

    tLogger := NewTimeLogger("TestTimeLogger")
    defer tLogger.Log()

    tLogger.AddPoint("start")
    time.Sleep(100 * time.Millisecond)
    tLogger.AddPointInc()
    time.Sleep(200 * time.Millisecond)

    for range 3 {
        tLogger.AddPointIncPrefix("loop")
        time.Sleep(50 * time.Millisecond)
    }
}

1

250609 11:55:57.046	[D]	time log [TestTimeLogger] sum[452ms] point list [key|add|sum] [start|+0|0] [1|+100|100] [loop-1|+200|300] [loop-2|+0|300] [loop-3|+50|351] [loop-4|+50|401] [end|+50|452] [unit_test.go:48]

打印调用栈

我们看到上面 zap 的示例中有一个 Debugw 方法，打印了调用栈。 但是我一直不太能很好的运用，问题在于“我应该在什么情况下打印调用栈呢”

我们假设方法 a 调用 b，b 再调用 c，当 c 报错时： 首先，a/b/c 遇到错误都打印调用栈，那么你会得到 3 次调用栈信息，很多是重复信息，类似这样

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

2025-06-09T14:12:38.747+0800	WARN	logger/unit_test.go:67	b
pgo/pkg/logger.TestLogErrReturn.func1
	g:/workspace/pgo/pkg/logger/unit_test.go:67
pgo/pkg/logger.b
	g:/workspace/pgo/pkg/logger/unit_test.go:58
pgo/pkg/logger.a
	g:/workspace/pgo/pkg/logger/unit_test.go:53
pgo/pkg/logger.TestLogErrReturn
	g:/workspace/pgo/pkg/logger/unit_test.go:67
testing.tRunner
	C:/Program Files/Go/src/testing/testing.go:1792
2025-06-09T14:12:38.747+0800	WARN	logger/unit_test.go:67	a
pgo/pkg/logger.TestLogErrReturn.func1
	g:/workspace/pgo/pkg/logger/unit_test.go:67
pgo/pkg/logger.a
	g:/workspace/pgo/pkg/logger/unit_test.go:54
pgo/pkg/logger.TestLogErrReturn
	g:/workspace/pgo/pkg/logger/unit_test.go:67
testing.tRunner
	C:/Program Files/Go/src/testing/testing.go:1792

优化成 c 打印调用栈，a 和 b 不打印，那么信息是简单又有效的。 这个问题是，但是如果现在 b 被复用，而 b 报错时没有打印调用栈。

又或者进一步的，b 的其他错误返回时打印调用栈，但其中调用 c 返回错误时，不打印错误。 这里提出了一个新的要求“所有方法自身的错误打印调用栈，而调用其他方法时，不打印” 我是不支持这个用法的，这增加了编码的心智负担，也增加后续维护时的工作量。 如果能坚持的话，我觉得这个方案是可行的，类似如下示例代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

func a(log func(args ...any)) error {
    if time.Now().Unix()%2 == 0 {
        // 自身函数错误需要打印日志
        err := errors.New("aa error")
        log(err.Error())
        return err
    }

    err := b(log)
    if err != nil {
        // 如果log方法会打印调用栈
        // 那么调用b不用打印日志
        // 因为b里面会输出调用栈
        // log("bb error")
        return err
    }

    return nil
}

func b(log func(args ...any)) error {
    err := errors.New("bb error")
    log(err.Error())
    return err
}
func TestLogErrReturn(t *testing.T) {
    InitLogger(true, zap.DebugLevel, "")
    a(Error)

    logger, _ := zap.NewDevelopment()
    defer logger.Sync()
    log := logger.Sugar()
    a(func(args ...any) { log.Warnw(args[0].(string)) })
}

我自己觉得比较高效的方案是“总是打印错误的发生，但不打印调用栈，配合代码片段使用”。 vscode 可以设置如下代码片段，让错误判断/打印/返回称为全项目统一的风格。 需要打印额外信息的，也在该基础上另外打印一条日志。

1
2
3
4
5
6
7
8
9

"log err and return": {
    "prefix": "ree",
    "body": [
        "if err != nil {",
        "    return logger.LogErr(err)",
        "}"
    ],
    "description": "打印并且返回错误"
},

则上面 a 方法改成这样

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

func a() error {
    if time.Now().Unix()%2 == 0 {
        return logger.LogErr(errors.New("aa error"))
    }

    err := b(log)
    if err != nil {
        return logger.LogErr(err)
    }

    err := b(log)
    logger.LogErr(err) // 只打印，不中断业务的错误处理

    return nil
}

顺便一提，在pgo中，我用自己的代码生成逻辑，很快就完成了调用代码的替换。 提交 1：模板代码的错误日志处理 提交 2：利用 genCurd 统一生成代码的错误日志处理

PS: 上面说 Debugw 打印调用栈，查看源码之后，发现是 zap.NewDevelopment()将设置 Development=true，但也不影响上面的论点。

1
2
3

// Development puts the logger in development mode, which changes the
// behavior of DPanicLevel and takes stacktraces more liberally.
Development bool `json:"development" yaml:"development"`

具体实现

PGO
Golang
This post is licensed under CC BY 4.0 by the author.