跳转至

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

你好，我是郑建勋。

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

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

输出如下所示：

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格式的日志，上面这个例子中的输出为：

{"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 可以被定制化。

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")
}

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

{"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和其他业务信息。规范日志示例如下：

{"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")
}

输出为：

{"level":"INFO","ts":"2022-10-14T23:59:15.701+0800","caller":"crawler/main.go:17","msg":"log init end"}

这样，我们就可以在项目中愉快地打印日志了。

总结

日志可以帮助我们了解程序的运行状态，在调试、问题定位、监控等场景下都有诸多的用处。

但是，Go标准库虽然提供了简单的日志功能，却不具备日志分级、结构化输出、日志切割、自定义输出格式的功能，性能也相对低下，我们一般在项目中并不能直接使用它。

好在满足我们使用需求的日志组件有很多，最出名的就有Zap、Logrus和Zerolog。其中，Zap在速度和内存分配上都有明显的优势。这节课，我们就封装了Zap来实现了项目的日志组件，并让它具备了可扩展、可切割的能力。后续日志的打印我们都将使用这个项目封装的日志组件。

课后题

今天的思考题是这样的。Go团队正在开发一个日志库slog，你觉得Go团队为什么要设置这个日志库，它和其他的日志库有什么区别？

欢迎你在留言区与我交流讨论，我们下节课见。

精选留言（8）
  • 奕 👍（2） 💬（1）

    建议把 Github 地址贴出来，只放到之前的章节里面，不太方便找到

    2022-12-06

  • Geek_cd6159 👍（0） 💬（1）

    gopkg.in/natefinch/lumberjack.v2 这个package怎么import成功啊 弄了半天都解决不了import问题

    2022-12-14

  • Geek_8ed998 👍（4） 💬（1）

    驴头不对马嘴，v0.1.1tag中根本没有log包，到了v0.1.2才有，而在1.1中又使用了log.NewFilePlugin。能不能上点心

    2023-07-12

  • 牙小木 👍（2） 💬（0）

    如果发现说的内容和贴的代码执行有偏差，可以借鉴以下代码，结合lumberjack，zap，log实现的一个简单的日志写入 ``` logger := &lumberjack.Logger{ Filename: "./logs/app_info.log", MaxSize: 5, // 日志的最大大小，以M为单位 MaxBackups: 3, // 保留的旧日志文件的最大数量 MaxAge: 28, // 保留旧日志文件的最大天数 Compress: false, } log.SetOutput(logger) for i := 0; i < 100; i++ { log.Printf("This is log entry %d", i) time.Sleep(time.Second) // 模拟日志写入间隔 } core := zapcore.NewCore( zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), zapcore.AddSync(logger), zap.InfoLevel, ) loggerInstance:=zap.New(core) zap.ReplaceGlobals(loggerInstance) // 写入一些日志 for i := 0; i < 100; i++ { zap.L().Info("This is anothr log entry", zap.Int("entryNumber", i)) time.Sleep(time.Second) // 模拟日志写入间隔 } defer loggerInstance.Sync() ```

    2023-08-18

  • 牙小木 👍（1） 💬（0）

    作者提到，本章代码是 https://github.com/dreamerjackson/crawler/releases/tag/v0.1.1 ，把这样的链接贴到文章末尾不就好了吗。 但是这个是不对的，因为没有log文件夹，写的人不仔细check，审的人也没有吗， 这是在极客时间上看到犯这种小错误最多的一个专栏了。还有王法吗，还有法律吗，狗头.JPG

    2023-08-18

  • Geek_755040 👍（0） 💬（0）

    怎么实现同时输出到命令行和日志呢，日志怎么按照日期进行拆分

    2023-06-08

  • 翡翠虎 👍（0） 💬（0）

    日志的规范那一段是不是漏了内容，就那一点吗？后续的监控、告警跟日志有关联性吗？怎么设置日志，才能够既保障错误排查，又满足可观测性需求呢？

    2022-12-20

  • 抱紧我的小鲤鱼 👍（0） 💬（0）

    个人觉得原因有二 1. 易用性 2. 性能

    2022-12-05