24、日志处理：日志规范与最佳实践

你好，我是郑建勋。

这节课，我们需要构建项目的日志组件，方便我们收集打印的日志信息。运行中的程序就像一个黑盒，好在日志为我们记录了系统在不同时刻的运行状态。日志的好处主要有下面四点。

打印调试：日志可以记录变量或者某一段逻辑，记录程序运行的流程。虽然用日志来调试通常被人认为是技术手段落后，但它确实能够解决某些难题。例如，一个场景线下无法复现，我们又不希望对线上系统产生破坏性的影响，这时打印调试就派上用场了。
问题定位：有时候，系统或者业务出现问题，我们需要快速排查原因，这时我们就要用到日志的功能了。例如，Go程序突然panic，被recover捕获之后，打印出当前的详细堆栈信息，就需要通过日志来定位。
用户行为分析：日志的大量数据可以作为大数据分析的基础，例如可以分析用户的行为偏好等。
监控：日志数据通过流处理生成的连续指标数据，可以存储起来并对接监控告警平台，这有助于我们快速发现系统的异常。监控的指标可能包括：核心接口调用量是否突然下降或上升，核心的业务指标（GMV是否同比和环比稳定，是否出现了不合理的订单，是否出现了零元或者天价账单）等。

标准库log

而Go语言标准库就为我们提供了一个简单的log日志库，我们先从它的使用方法讲起。

标准库log提供了3个打印日志的接口，分别为log.Println、log.Fatalln 和log.Panicln 。另外log还可以通过log.SetPrefix 设置打印日志时的前缀，通过log.SetFlags 设置打印的时间和文件的格式。

我们举一个简单的例子，下面这段代码使用了Go标准库。log.SetFlags中的参数log.Ldate 代表日志会打印日期，log.Lmicroseconds代表日志会打印微秒，log.Llongfile的意思是日志会输出长文件名的形式。

func init() {
	log.SetPrefix("TRACE: ")
	log.SetFlags(log.Ldate | log.Lmicroseconds | log.Llongfile)
}

func main() {
	log.Println("message")
	log.Fatalln("fatal message")
	log.Panicln("panic message")
}

输出如下所示：

1 2	TRACE: 2022/10/12 22:22:36.540776 a/b/main.go:19: message TRACE: 2022/10/12 22:22:36.541046 a/b/main.go:20: fatal message

要注意的是，log.Fatalln 会调用os.Exit(1)强制退出程序，所以就算没有打印出第三条日志，log.Panicln也会使程序panic，但是我们可以通过recover完成捕获。

可能你已经发现了，标准log库的不足之处在于，无法对日志进行分级，在生产环境中日志可能会有DEBUG、INFO等级别。并且我们也并不希望在打印日志时触发panic，或者让程序直接退出。

log提供了一些扩展能力，它让我们可以自定义不同级别的日志，例如借助 log.New 完成日志分级的功能，log.New 可以指定新log的输出位置、日志的前缀和格式。Error.Println最终会将数据输出到文件中。

var (
	Error   *log.Logger
	Warning *log.Logger
)

func init() {
	file, err := os.OpenFile("errors.txt",
		os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
	if err != nil {
		log.Fatalln("Failed to open error log file:", err)
	}

	Warning = log.New(os.Stdout,
		"WARNING: ",
		log.Ldate|log.Ltime|log.Lshortfile)

	Error = log.New(file,
		"ERROR: ",
		log.Ldate|log.Ltime|log.Lshortfile)
}

func main() {
	Warning.Println("There is something you need to know about")
	Error.Println("Something has failed")
}

虽然提供了有限的扩展能力，标准库log仍然存在一些不足之处（例如对参数的处理借助了 fmt.Sprintxxx 函数，中间包含了大量反射，性能比较低下；而且log不会输出类似JSON的结构化数据，要想实现文件切割也比较困难），所以我们一般是在本地开发环境中使用它。

那么一个工业级的日志组件应该具备什么特性呢，我列出了一些需要考虑的点：

不同的环境有不同的输出行为，比如测试和开发环境要输出到控制台，而生产环境则要输出到文件中；
日志分等级；
类似JSON的结构化输出，这会使日志更容易阅读，也有助于后续查找和存储日志；
支持日志文件切割（可以按照日期、时间间隔或者文件大小对日志进行切割）；
可以定义输出的格式，例如打印日志的函数、所在的文件、行号、记录时间等；
速度快。

Zap

在Go语言中，满足这些条件而且比较知名的日志库有Zap、Logrus和Zerolog。

其中，Zap是Uber开源的日志组件，当前在社区非常受欢迎。在满足了日志库应该具备的基本功能的基础上，Zap在内存分配量与速度方面相比其他日志组件都有较大的优势。所以在我们后面的项目中将通过封装Zap来实现日志的打印能力。

Zap 提供了两种类型的日志，分别是Logger 与 SugaredLogger。其中，Logger是默认的，每个要写入的字段都得指定对应类型的方法，这种方式可以不使用反射，因此效率更高。为了避免在异常情况下丢失日志（尤其是在崩溃时），logger.Sync()会在进程退出之前落盘所有位于缓冲区中的日志条目。

package main
import "go.uber.org/zap"
func main() {
	logger, _ := zap.NewProduction()
	defer logger.Sync()
	url := "www.google.com"
	logger.Info("failed to fetch URL",
		zap.String("url", url),
		zap.Int("attempt", 3),
		zap.Duration("backoff", time.Second))
}

而SugaredLogger的性能稍微低于Logger，但是它提供了一种更灵活的打印方式：

func main() {
	logger, _ := zap.NewProduction()
	defer logger.Sync()
	sugar := logger.Sugar()
	url := "www.google.com"
	sugar.Infow("failed to fetch URL",
		"url", url,
		"attempt", 3,
		"backoff", time.Second,
	)
}

Zap在默认情况下会输出JSON格式的日志，上面这个例子中的输出为：

1	{"level":"info","ts":1665669124.251897,"caller":"a/b.go:20","msg":"failed to fetch URL","url":"www.google.com","attempt":3,"backoff":1}

Zap预置了3种格式的Logger，分别为 zap.NewExample()、zap.NewDevelopment() 和 zap.NewProduction() 。这 3 个函数可以传入若干类型为 zap.Option 的选项，从而扩展Logger 的行为。选项包括zap.WithCaller打印文件、行号、zap.AddStacktrace 打印堆栈信息。

除此之外，我们还可以定制自己的Logger，提供比预置的Logger更灵活的能力。举一个例子，zap.NewProduction() 实际调用了NewProductionConfig().Build()，而NewProductionConfig()生成的 zap.Config 可以被定制化。

1
2
3

func NewProduction(options ...Option) (*Logger, error) {
	return NewProductionConfig().Build(options...)
}

在下面这个例子中，我修改了Zap中打印时间的格式：

func main() {
	loggerConfig := zap.NewProductionConfig()
	loggerConfig.EncoderConfig.TimeKey = "timestamp"
	loggerConfig.EncoderConfig.EncodeTime = zapcore.TimeEncoderOfLayout(time.RFC3339)

	logger, err := loggerConfig.Build()
	if err != nil {
		log.Fatal(err)
	}

	sugar := logger.Sugar()

	sugar.Info("Hello from zap logger")
}

输出如下，根据合理灵活的日志格式配置，我们就可以满足项目的不同需要了。

1	{"level":"info","timestamp":"2022-10-13T23:12:17+08:00","caller":"a/main.go:169","msg":"Hello from zap logger"}

日志切割

在Zap中，我们也可以通过底层的Zap.New函数的扩展能力完成更加定制化的操作。例如，指定日志输出的Writer行为。

不同的Writer可能有不同的写入行为，像是输出到文件还是控制台，是否需要根据时间和文件的大小对日志进行切割等。Zap将日志切割的能力开放了出来，只要日志切割组件实现了zapcore.WriteSyncer 接口，就可以集成到Zap中。比较常用的日志切割组件为 lumberjack.v2 。下面这个例子将 lumberjack.v2 组件集成到了 Zap 中：

w := &lumberjack.Logger{
  Filename:   "/var/log/myapp/foo.log",
  MaxSize:    500, // 日志的最大大小，以M为单位
  MaxBackups: 3,  // 保留的旧日志文件的最大数量
  MaxAge:     28, // 保留旧日志文件的最大天数
}
core := zapcore.NewCore(
  zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()),
  w,
  zap.InfoLevel,
)
logger := zap.New(core)

日志分级

设置好日志组件的基本属性之后就可以打印日志了。在输出日志时，我们需要根据日志的用途进行分级。目前最佳的实践是将日志级别分为了五类。

DEBUG
DEBUG 级别的日志，顾名思义主要是用来调试的。通过打印当前程序的调用链，我们可以知道程序运行的逻辑，了解关键分支中详细的变量信息、上下游请求参数和耗时等，帮助开发者调试错误，判断逻辑是否符合预期。DEBUG日志一般用在开发和测试初期。不过，由于太多的DEBUG日志会降低线上程序的性能、同时导致成本上升，因此，在生产环境中一般不会打印DEBUG日志。
INFO
INFO 级别的日志记录了系统中核心的指标。例如，初始化时配置文件的路径，程序所处集群的环境和版本号，核心指标和状态的变化；再比如，监听到外部节点数量的变化，或者外部数据库地址的变化。INFO信息有助于我们了解程序的整体运行情况，快速排查问题。
WARNING
WARNING 级别的日志用于输出程序中预知的，程序目前仍然能够处理的问题。例如，打车服务中，行程信息会存储在缓存中方便我们快速查找。但是如果在缓存中查不到用户的行程信息，这时我们可以用一些兜底的策略重建行程，继续完成后续的流程。这种不影响正常流程，但又不太符合预期的情况就适合用WARNING。WARNING还可以帮助我们在事后分析异常情况出现的原因。
ERROR
ERROR 级别的日志主要针对一些不可预知的问题，例如网络通信或者数据库连接的异常等。
FATAL
FATAL级别的日志主要针对程序遇到的严重问题，意味着需要立即终止程序。例如遇到了不能容忍的并发冲突时，就应该使用FATAL级别的日志。

Zap日志库在上面五个分级的基础上还增加了Panic和DPanic级别，如下所示。Panic级别打印后会触发panic。而DPanic级别比较特殊，它在development模式下会panic，相当于PanicLevel级别，而在其他模式下相当于ErrorLevel级别。

const (
	DebugLevel = zapcore.DebugLevel
	InfoLevel = zapcore.InfoLevel
	WarnLevel = zapcore.WarnLevel
	ErrorLevel = zapcore.ErrorLevel
	DPanicLevel = zapcore.DPanicLevel
	PanicLevel = zapcore.PanicLevel
	FatalLevel = zapcore.FatalLevel
)

日志格式规范

对于打印出来的日志格式，我们希望它尽量符合通用的规范，以便公共的采集通道进行进一步的日志处理。一个合格的日志至少应该有具体的时间、打印的行号、日志级别等重要信息。同时，在大规模的集群中，还可能包含机器的IP地址，调用者IP和其他业务信息。规范日志示例如下：

1	{"level":"info","timestamp":"2022-10-13T23:29:10+08:00","caller":"a/main.go:168","msg":"data","orderid":1414281843,"traceid":124111424,"appversion":"v1.1","caller_ip":"10.8.0.1","reason_type":30}

下面列出一个实际中在使用的日志规范，可以作为一个参考：

每一行日志必须至少包含日志Key、TimeStamp、打印的行号、日志级别字段；
单条日志长度在1MB以内，单个服务节点每秒的日志量小于20MB；
建议使用UTF-8字符集，避免入库时出现乱码；
Key为每个字段的字段名，一行示例中的Key是唯一的；
Key的命名只能包含数字、字母、下划线，且必须以字母开头；
Key的长度不可大于80个字符；
Key中的字母均为小写。

构建项目日志组件

接下来，让我们利用Zap构建项目的日志组件，将代码放入到新的log文件夹中。关于日志组件的代码，你可以查看代码库v0.1.1分支。

我们把 zapcore.Core 作为一个自定义类型 Plugin ，zapcore.Core 定义了日志的编码格式以及输出位置等核心功能。作为一个通用的库，下面我们实现了NewStdoutPlugin、NewStderrPlugin、NewFilePlugin 这三个函数，分别对应了输出日志到stdout、stderr和文件中。这三个函数最终都调用了zapcore.NewCore函数。

type Plugin = zapcore.Core

func NewStdoutPlugin(enabler zapcore.LevelEnabler) Plugin {
	return NewPlugin(zapcore.Lock(zapcore.AddSync(os.Stdout)), enabler)
}

func NewStderrPlugin(enabler zapcore.LevelEnabler) Plugin {
	return NewPlugin(zapcore.Lock(zapcore.AddSync(os.Stderr)), enabler)
}

// Lumberjack logger虽然持有File但没有暴露sync方法，所以没办法利用zap的sync特性
// 所以额外返回一个closer，需要保证在进程退出前close以保证写入的内容可以全部刷到磁盘
func NewFilePlugin(
	filePath string, enabler zapcore.LevelEnabler) (Plugin, io.Closer) {
	var writer = DefaultLumberjackLogger()
	writer.Filename = filePath
	return NewPlugin(zapcore.AddSync(writer), enabler), writer
}

func NewPlugin(writer zapcore.WriteSyncer, enabler zapcore.LevelEnabler) Plugin {
	return zapcore.NewCore(DefaultEncoder(), writer, enabler)
}

NewFilePlugin 中暴露出了两个参数：filePath 和 enabler。filePath表示输出文件的路径，而enabler代表当前环境中要打印的日志级别。刚才我们梳理了Zap中的七种日志级别，它们是一个整数，按照等级从上到下排列的，等级最低的是Debug，等级最高的为Fatal。在生产环境中，我们并不希望打印Debug日志，因此我们可以在生产环境中指定enabler参数为InfoLevel级别，这样，就只有大于等于enabler的日志等级才会被打印了。

const (
	DebugLevel = zapcore.DebugLevel
	InfoLevel = zapcore.InfoLevel
	WarnLevel = zapcore.WarnLevel
	ErrorLevel = zapcore.ErrorLevel
	DPanicLevel = zapcore.DPanicLevel
	PanicLevel = zapcore.PanicLevel
	FatalLevel = zapcore.FatalLevel
)

下一步是日志切割，在 NewFilePlugin 中，我们借助 lumberjack.v2 来完成日志的切割。

// 1.不会自动清理backup
// 2.每200MB压缩一次，不按时间切割
func DefaultLumberjackLogger() *lumberjack.Logger {
	return &lumberjack.Logger{
		MaxSize:   200,
		LocalTime: true,
		Compress:  true,
	}
}

最后，我们要暴露一个通用的函数NewLogger来生成logger。默认的选项会打印调用时的文件与行号，并且只有当日志等级在DPanic等级之上时，才输出函数的堆栈信息。

func NewLogger(plugin zapcore.Core, options ...zap.Option) *zap.Logger {
	return zap.New(plugin, append(DefaultOption(), options...)...)
}

func DefaultOption() []zap.Option {
	var stackTraceLevel zap.LevelEnablerFunc = func(level zapcore.Level) bool {
		return level >= zapcore.DPanicLevel
	}
	return []zap.Option{
		zap.AddCaller(),
		zap.AddStacktrace(stackTraceLevel),
	}
}

现在让我们在main函数中集成log组件，文件名和日志级别现在是写死的，后续我们会统一放入到配置文件中。

func main() {
	plugin, c := log.NewFilePlugin("./log.txt", zapcore.InfoLevel)
	defer c.Close()
	logger := log.NewLogger(plugin)
	logger.Info("log init end")
}

输出为：