从Go log库到Zap,怎么打造出好用又实用的Logger

日志无论对于程序还是程序员都非常重要,有多重要呢,想要长期在公司健健康康的干下去就得学会阶段性划水,阶段性划水的一大关键的就是干活快过预期但是装作。。。不对,这个开头不对劲,下面重来。

日志无论对于程序还是程序员都非常重要,程序员解决问题的快慢除了经验外,就是看日志能不能有效地记录问题发生的现场以及上下文等等。

那么让让程序记录有效的日志,除了程序内记日志的点位尽量精准外,还需要有一个称手的 Logger 。一个好的 Logger (日志记录器) 要能提供以下这些能力

  • 支持把日志写入到多个输出流中,比如可以选择性的让测试、开发环境同时向控制台和日志文件输出日志,生产环境只输出到文件中。
  • 支持多级别的日志等级,比如常见的有:TRACEDEBUGINFOWARNERROR 等。
  • 支持结构化输出,结构化输出现在常用的就是JSON形式的,这样可以让统一日志平台,通过 logstash 之类的组件直接把日志聚合到日志平台上去。
  • 需要支持日志切割 -- log rotation, 按照日期、时间间隔或者文件大小对日志进行切割。
  • 在 Log Entry 中(就是每行记录)除了主动记录的信息外,还要包括如打印日志的函数、所在的文件、行号、记录时间等。

今天我带大家一起看看怎么在使用 Go 语言开发的项目里打造一个称手的 Logger,在这之前让我们先回到 2009 年,看看 Go 语言自诞生之初就提供给我们的内置 Logger。

Go 语言原生的Logger

Go 语言自带 log 内置包,为我们提供了一个默认的 Logger,可以直接使用。 这个库的详细用法可以在官方的文档里找到:pkg.go.dev/log

使用 log 记录日志,默认会输出到控制台中。比如下面这个例子:

package main

import (
	"log"
	"net/http"
)

func main() {
	simpleHttpGet("www.google.com")
	simpleHttpGet("https://www.baidu.com")
}

func simpleHttpGet(url string) {
	resp, err := http.Get(url)
	if err != nil {
		log.Printf("Error fetching url %s : %s", url, err.Error())
	} else {
		log.Printf("Status Code for %s : %s", url, resp.Status)
		resp.Body.Close()
	}
	return
}

这个例程中,分别向两个网址进行 GET 请求,然后记录了一下返回状态码 / 请求错误。 执行程序后会有类似输出:

2022/05/15 15:15:26 Error fetching url www.baidu.com : Get "www.baidu.com": unsupported protocol scheme ""
2022/05/15 15:15:26 Status Code for https://www.baidu.com : 200 OK

因为第一次请求的 URL 中协议头缺失, 所以不能成功发起请求,日志也很好的记录了错误信息。

Go 内置的 log 包当然也支持把日志输出到文件中,通过log.SetOutput 可以把任何 io.Writer 的实现设置成日志的输出。下面我们把上面那个例程修改成向文件输出日志。

package main

import (
	"log"
	"net/http"
	"os"
)

func main() {
	SetupLogger()
	simpleHttpGet("www.baidu.com")
	simpleHttpGet("https://www.baidu.com")
}

func SetupLogger() {
	logFileLocation, _ := os.OpenFile("/tmp/test.log", os.O_CREATE|os.O_APPEND|os.O_RDWR, 0644)
	log.SetOutput(logFileLocation)
}

func simpleHttpGet(url string) {
	resp, err := http.Get(url)
	if err != nil {
		log.Printf("Error fetching url %s : %s", url, err.Error())
	} else {
		log.Printf("Status Code for %s : %s", url, resp.Status)
		resp.Body.Close()
	}
	return
}

大家可以自己试一下运行效果,这里不再做过多演示。

Go 语言原生Logger的缺点

原生 Logger 的优点,显而易见,简单、开箱即用,不用引用外部的三方库。我们可以按照开头处提出的对于一个 Logger 的五个标准再看一下默认Logger 是否能在项目里使用。

  • 仅限基本的日志级别
    • 只有一个Print选项。不支持INFO/DEBUG等多个级别。
  • 对于错误日志,它有FatalPanic
    • Fatal日志通过调用os.Exit(1)来结束程序
    • Panic日志在写入日志消息之后抛出一个panic
    • 但是它缺少一个ERROR日志级别,这个级别可以在不抛出panic或退出程序的情况下记录错误
  • 缺乏结构化日志格式的能力——只支持简单文本输出,不能把日志记录格式化成 JSON 格式。
  • 不提供日志切割的能力。

Zap 日志库

在 Go 的生态中,有不少可以选择的日志库,之前我们简单介绍过 logrus 这个库的使用:点我查看,它与Go的内置 log 库在 api 层面兼容,直接实现了log.Logger接口,支持把程序的系统级 Logger 切换成它。

不过 logrus 在性能敏感的场景下就显得不香了,用的更多的是 Uber 开源的 zap 日志库。由于 Uber 在当今 Go 生态中的贡献度很高,加之它本身业务—网约车的性能敏感场景,所以 Uber 开源的库很受欢迎。现在做项目,使用 Zap 做日志Logger 的非常多。程序员的内心OS应该是,不管我这并发高不高,上就完事了,万一哪天能从2个并发突然干成 2W 并发呢。

Zap 性能高的一大原因是:不用反射,日志里每个要写入的字段都得携带着类型

logger.Info(
  "Success..",
  zap.String("statusCode", resp.Status),
  zap.String("url", url))

上面向日志里写入了一条记录,Message 是 "Success.." 另外写入了两个字符串键值对。 Zap 针对日志里要写入的字段,每个类型都有一个对应的方法把字段转成 zap.Field 类型 。比如:

zap.Int('key', 123)
zap.Bool('key', true)
zap.Error('err', err)
zap.Any('arbitraryType', &User{})

还有很多中这种类型方法,就不一一列举啦。这种记录日志的方式造成在使用体验上稍稍有点差,不过考虑到性能上收益这点使用体验上的损失也能接受。

下面我们先来学习一下 Zap 的使用方法,再对项目中使用 Zap 时做些自定义的配置和封装,让它变得更好用,最重要的是匹配上我们开头提出的关于好的 Logger 的五条标准。

Zap 的使用方法

安装zap

首先说一下,zap 的安装方式,直接运行以下命令下载 zap 到本地的依赖库中。

go get -u go.uber.org/zap

设置 Logger

我们先说 zap 提供的配置好的 Logger ,稍后会对它进行自定义。

  • 通过调用zap.NewProduction()zap.NewDevelopment()zap.Example() 这三个方法,都可以创建 Logger。
  • 上面三个方法都可以创建 Logger,他们都对 Logger 进行了不同的配置,比如zap.NewProduction()创建的 Logger 在记录日志时会自动记录调用函数的信息、打日志的时间等,这三个不用纠结,直接都用zap.NewProduction(),且在项目中使用的时候,我们不会直接用 zap 配置好的 Logger ,需要再做更细致的定制。

zap 的 Logger 提供了记录不同等级的日志的方法,像从低到高的日志等级一般有:Debug、Info、Warn、Error 这些级别都有对应的方法。他们的使用方式都一样,下面是 Info 方法的方法签名。

func (log *Logger) Info(msg string, fields ...Field) {
	if ce := log.check(InfoLevel, msg); ce != nil {
		ce.Write(fields...)
	}
}

方法的第一个参数是日志里 msg 字段要记录的信息,msg是日志行记录里一个固定的字段,要再添加其他字段到日志,直接传递 zap.Field 类型的参数即可,上面我们已经说过zap.Field类型的字段,就是由 zap.String("key", "value") 这类方法创建出来的。由于 Info 方法签名里 fileds参数声明是可变参数,所以支持添加任意多个字段到日志行记录里, 比如例程里的:

logger.Info("Success..", zap.String("statusCode", resp.Status), zap.String("url", url))

即日志行记录里,除了 msg 字段,还添加了statusCodeurl两个自定义字段。 上面例程里使用的zap.NewProduction()创建的 Logger 会向控制台输出JSON格式的日志行,比如上面使用Info方法后,控制台会有类似下面的输出。

{"level":"info","ts":1558882294.665447,"caller":"basiclogger/UberGoLogger.go:31","msg":"Success..","statusCode":"200 OK","url":"https://www.baidu.com"}

定制 Zap 的 Logger

下面我们把 zap 做进一步的自定义配置,让日志不光能输出到控制台,也能输出到文件,再把日志时间由时间戳格式,换成更容易被人类看懂的DateTime时间格式。

下面少说话,直接上代码,必要的解释放在了注释里。

var logger *zap.Logger

func init() {
	encoderConfig := zap.NewProductionEncoderConfig()
  // 设置日志记录中时间的格式
	encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
  // 日志Encoder 还是JSONEncoder,把日志行格式化成JSON格式的
	encoder := zapcore.NewJSONEncoder(encoderConfig)

	file, _ := os.OpenFile("/tmp/test.log", os.O_CREATE|os.O_APPEND|os.O_WRONLY, 644)
	fileWriteSyncer = zapcore.AddSync(file)
  
	core := zapcore.NewTee(
		// 同时向控制台和文件写日志, 生产环境记得把控制台写入去掉,日志记录的基本是Debug 及以上,生产环境记得改成Info
		zapcore.NewCore(encoder, zapcore.AddSync(os.Stdout), zapcore.DebugLevel),
		zapcore.NewCore(encoder, fileWriteSyncer, zapcore.DebugLevel),
	)
	logger = zap.New(core)
}

日志切割

Zap 本身不支持日志切割,可以借助另外一个库 lumberjack 协助完成切割。

func getFileLogWriter() (writeSyncer zapcore.WriteSyncer) {
	// 使用 lumberjack 实现 log rotate
	lumberJackLogger := &lumberjack.Logger{
		Filename:   "/tmp/test.log",
		MaxSize:    100, // 单个文件最大100M
		MaxBackups: 60, // 多于 60 个日志文件后,清理较旧的日志
		MaxAge:     1, // 一天一切割
		Compress:   false,
	}

	return zapcore.AddSync(lumberJackLogger)
}

封装 Logger

我们不能每次使用日志,都这么设置一番,所以最好的还是把这些配置初始化放在一个单独的包里,这样在项目中初始化一次即可。

除了上面的那些配置外,我们的配置里还少了些日志调用方的信息,比如函数名、文件位置、行号等,这样在排查问题看日志的时候,定位问题的时效会提高不少。

我们对 Logger 再做一下封装。

// 发送私信 go-logger 给公众号「网管叨bi叨」
// 可获得完整代码和使用Demo
package zlog

// 简单封装一下对 zap 日志库的使用
// 使用方式:
// zlog.Debug("hello", zap.String("name", "Kevin"), zap.Any("arbitraryObj", dummyObject))
// zlog.Info("hello", zap.String("name", "Kevin"), zap.Any("arbitraryObj", dummyObject))
// zlog.Warn("hello", zap.String("name", "Kevin"), zap.Any("arbitraryObj", dummyObject))
var logger *zap.Logger

func init() {
	......
}

func getFileLogWriter() (writeSyncer zapcore.WriteSyncer) {
	......
}

func Info(message string, fields ...zap.Field) {
	callerFields := getCallerInfoForLog()
	fields = append(fields, callerFields...)
	logger.Info(message, fields...)
}

func Debug(message string, fields ...zap.Field) {
	callerFields := getCallerInfoForLog()
	fields = append(fields, callerFields...)
	logger.Debug(message, fields...)
}

func Error(message string, fields ...zap.Field) {
	callerFields := getCallerInfoForLog()
	fields = append(fields, callerFields...)
	logger.Error(message, fields...)
}

func Warn(message string, fields ...zap.Field) {
	callerFields := getCallerInfoForLog()
	fields = append(fields, callerFields...)
	logger.Warn(message, fields...)
}

func getCallerInfoForLog() (callerFields []zap.Field) {

	pc, file, line, ok := runtime.Caller(2) // 回溯两层,拿到写日志的调用方的函数信息
	if !ok {
		return
	}
	funcName := runtime.FuncForPC(pc).Name()
	funcName = path.Base(funcName) //Base函数返回路径的最后一个元素,只保留函数名

	callerFields = append(callerFields, zap.String("func", funcName), zap.String("file", file), zap.Int("line", line))
	return
}

为啥不用 zap.New(core, zap.AddCaller())这种方式,在日志行里添加调用方的信息呢?主要还是想更灵活点,能自己制定对应的日志字段,所以把 Caller的几个信息放到单独的字段里,等把日志收集到日志平台上去后,查询日志的时候也更利于检索。

在下面的例程中尝试使用我们封装好的日志 Logger 做个简单的测试。

package main

import (
	"example.com/utils/zlog"
)

type User strunct {
  Name  stirng
}

func main() {

  user := &User{
    "Name": "Kevin"
  }
  zlog.Info("test log", zap.Any("user", user))
}

输出类似下面的输出。

{"level":"info","ts":"2022-05-15T21:22:22.687+0800","msg":"test log","res":{"Name":"Kevin"},"func":"main.Main","file":"/Users/Kevin/go/src/example.com/demo/zap.go","line":84}

总结

关于 Zap Logger 的定制化和封装,这里只是举了一些基本又必要的入门级定制化,等大家掌握后,可以参照官方文档提供的接口进行更多定制化。

为了阅读体验文章中的代码随着内容演进分落在了不同段落里,需要完整源代码的可在「网管叨bi叨」公众号后台回复 go-logger 自取。