20-日志处理（上）：如何设计日志包并记录日志？

通过记录日志，可以完成一些基本功能，比如开发、测试期间的Debug，故障排除，数据分析，监控告警，以及记录发生的事件等。

如何设计日志包

基础功能

基础功能，是优秀日志包必备的功能，能够满足绝大部分的使用场景，适合一些中小型的项目。一个日志包应该具备以下4个基础功能。

支持基本的日志信息

日志包需要支持基本的日志信息，包括时间戳、文件名、行号、日志级别和日志信息。

时间戳可以记录日志发生的时间。在定位问题时，我们往往需要根据时间戳，来复原请求过程，核对相同时间戳下的上下文，从而定位出问题。

文件名和行号，可以使我们更快速定位到打印日志的位置，找到问题代码。一个日志库如果不支持文件名和行号，排查故障就会变得非常困难，基本只能靠grep和记忆来定位代码。

通过日志级别，可以知道日志的错误类型，最通常的用法是：直接过滤出 Error 级别的日志，这样就可以直接定位出问题出错点，然后再结合其他日志定位出出错的原因。

而通过日志信息，我们可以知道错误发生的具体原因。

支持不同的日志级别

通常一个日志包至少要实现6个级别，我给你提供了一张表格，按优先级从低到高排列如下：

有些日志包，例如logrus，还支持Trace日志级别。Trace级别比Debug级别还低，能够打印更细粒度的日志信息。

打印日志时，一个日志调用其实具有两个属性：

输出级别：打印日志时，我们期望日志的输出级别。例如，我们调用 glog.Info("This is info message") 打印一条日志，则输出日志级别为Info。
开关级别：启动应用程序时，期望哪些输出级别的日志被打印。例如，使用glog时 -v=4 ，说明了只有日志级别高于4的日志才会被打印。

如果开关级别设置为 L ，只有输出级别 >=L 时，日志才会被打印。例如，开关级别为Warn，则只会记录Warn、Error 、Panic 和Fatal级别的日志。具体的输出关系如下图所示：

支持自定义配置

支持输出到标准输出和文件

日志总是要被读的，要么输出到标准输出，供开发者实时读取，要么保存到文件，供开发者日后查看。输出到标准输出和保存到文件是一个日志包最基本的功能。

高级功能

支持多种日志格式

日志格式也是我们要考虑的一个点，一个好的日志格式，不仅方便查看日志，还能方便一些日志采集组件采集日志，并对接类似Elasticsearch这样的日志搜索引擎。

一个日志包至少需要提供以下两种格式：

TEXT格式：TEXT格式的日志具有良好的可读性，可以方便我们在开发联调阶段查看日志，例如：

2020-12-02T01:16:18+08:00 INFO example.go:11 std log

2020-12-02T01:16:18+08:00 DEBUG example.go:13 change std log to debug level

JSON格式：JSON格式的日志可以记录更详细的信息，日志中包含一些通用的或自定义的字段，可供日后的查询、分析使用，而且可以很方便地供filebeat、logstash这类日志采集工具采集并上报。下面是JSON格式的日志：

{"level":"DEBUG","time":"2020-12-02T01:16:18+08:00","file":"example.go:15","func":"main.main","message":"log in json format"}
{"level":"INFO","time":"2020-12-02T01:16:18+08:00","file":"example.go:16","func":"main.main","message":"another log in json format"}

我建议在开发联调阶段使用TEXT格式的日志，在现网环境使用JSON格式的日志。一个优秀的日志库，例如logrus，除了提供基本的输出格式外，还应该允许开发者自定义日志输出格式。

能够按级别分类输出

为了能够快速定位到需要的日志，一个比较好的做法是将日志按级别分类输出，至少错误级别的日志可以输出到独立的文件中。这样，出现问题时，可以直接查找错误文件定位问题。例如，glog就支持分类输出，如下图所示：

支持结构化日志

结构化日志（Structured Logging），就是使用JSON或者其他编码方式使日志结构化，这样可以方便后续使用Filebeat、Logstash Shipper等各种工具，对日志进行采集、过滤、分析和查找。使用zap进行日志打印：

package main

import (
    "time"

    "go.uber.org/zap"
)

func main() {
    logger, _ := zap.NewProduction()
    defer logger.Sync() // flushes buffer, if any
    url := "http://marmotedu.com"
    // 结构化日志打印
    logger.Sugar().Infow("failed to fetch URL", "url", url, "attempt", 3, "backoff", time.Second)

    // 非结构化日志打印
    logger.Sugar().Infof("failed to fetch URL: %s", url)
}

上述代码输出为：

{"level":"info","ts":1607303966.9903321,"caller":"zap/structured_log.go:14","msg":"failed to fetch URL","url":"http://marmotedu.com","attempt":3,"backoff":1}
{"level":"info","ts":1607303966.9904354,"caller":"zap/structured_log.go:17","msg":"failed to fetch URL: http://marmotedu.com"}

支持日志轮转

在一个大型项目中，一天可能会产生几十个G的日志。为了防止日志把磁盘空间占满，导致服务器或者程序异常，就需要确保日志大小达到一定量级时，对日志进行切割、压缩，并转存。

如何切割呢？你可以按照日志大小进行切割，也可以按日期切割。日志的切割、压缩和转存功能可以基于GitHub上一些优秀的开源包来封装，例如：lumberjack可以支持按大小和日期归档日志，file-rotatelogs支持按小时数进行日志切割。

对于日志轮转功能，因为这会增加日志包的复杂度，我更建议的做法是借助其他的工具来实现日志轮转。例如，在Linux系统中可以使用Logrotate来轮转日志。

具备Hook能力

当某个级别的日志产生时，发送邮件或者调用告警接口进行告警。很多优秀的开源日志包提供了 Hook能力，例如logrus和zap。

可选功能

支持颜色输出

在开发、测试时开启颜色输出，不同级别的日志会被不同颜色标识，这样我们可以很轻松地发现一些Error、Warn级别的日志，方便开发调试。发布到生产环境时，可以关闭颜色输出，以提高性能。

兼容标准库log包

一些早期的Go项目大量使用了标准库log包，如果我们的日志库能够兼容标准库log包，我们就可以很容易地替换掉标准库log包。例如，logrus就兼容标准库log包。这里，我们来看一个使用了标准库log包的代码：

package main

import (
    "log"
)

func main() {
    log.Print("call Print: line1")
    log.Println("call Println: line2")
}

只需要使用log "github.com/sirupsen/logrus"替换"log"就可以完成标准库log包的切换：

package main

import (
    log "github.com/sirupsen/logrus"
)

func main() {
    log.Print("call Print: line1")
    log.Println("call Println: line2")
}

支持输出到不同的位置

分别需要把日志投递到Elasticsearch、Kafka等组件，如果我们的日志包支持将日志投递到不同的目的端：

设计日志包时需要关注的点

我们还需要关注的几个层面：

高性能：因为我们要在代码中频繁调用日志包，记录日志，所以日志包的性能是首先要考虑的点，一个性能很差的日志包必然会导致整个应用性能很差。
并发安全：Go应用程序会大量使用Go语言的并发特性，也就意味着需要并发地记录日志，这就需要日志包是并发安全的。
插件化能力：日志包应该能提供一些插件化的能力，比如允许开发者自定义输出格式，自定义存储位置，自定义错误发生时的行为（例如告警、发邮件等）。插件化的能力不是必需的，因为日志自身的特性就能满足绝大部分的使用需求，例如：输出格式支持JSON和TEXT，存储位置支持标准输出和文件，日志监控可以通过一些旁路系统来实现。
日志参数控制：日志包应该能够灵活地进行配置，初始化时配置或者程序运行时配置。例如：初始化配置可以通过 Init 函数完成，运行时配置可以通过 SetOptions / SetLevel 等函数来完成。

如何记录日志？

想要更好地记录日志，我们需要解决以下几个问题：

在何处打印日志？

日志主要是用来定位问题的，所以整体来说，我们要在有需要的地方打印日志。那么具体是哪些地方呢？

在分支语句处打印日志。在分支语句处打印日志，可以判断出代码走了哪个分支，有助于判断请求的下一跳，继而继续排查问题。
写操作必须打印日志。写操作最可能会引起比较严重的业务故障，写操作打印日志，可以在出问题时找到关键信息。
在循环中打印日志要慎重。如果循环次数过多，会导致打印大量的日志，严重拖累代码的性能，建议的办法是在循环中记录要点，在循环外面总结打印出来。
在错误产生的最原始位置打印日志。对于嵌套的Error，可在Error产生的最初位置打印Error日志，上层如果不需要添加必要的信息，可以直接返回下层的Error。我给你举个例子：

package main

import (
    "flag"
    "fmt"

    "github.com/golang/glog"
)

func main() {
    flag.Parse()
    defer glog.Flush()

    if err := loadConfig(); err != nil {
        glog.Error(err)
    }
}

func loadConfig() error {
    return decodeConfig() // 直接返回
}

func decodeConfig() error {
    if err := readConfig(); err != nil {
        return fmt.Errorf("could not decode configuration data for user %s: %v", "colin", err) // 添加必要的信息，用户名称
    }

    return nil
}

func readConfig() error {
    glog.Errorf("read: end of input.")
    return fmt.Errorf("read: end of input")
}

当代码调用第三方包的函数，且第三方包函数出错时，会打印错误信息。比如：

if err := os.Chdir("/root"); err != nil {
    log.Errorf("change dir failed: %v", err)
}

在哪个日志级别打印日志？

Debug级别

为了获取足够的信息进行Debug，通常会在Debug级别打印很多日志。例如，可以打印整个HTTP请求的请求Body或者响应Body。

Debug这个级别的日志可以随意输出，任何你觉得有助于开发、测试阶段调试的日志，都可以在这个级别打印。

Info级别

一些关键日志，可以在Info级别记录，但如果日志量大、输出频度过高，则要考虑在Debug级别记录。

现网的日志级别一般是Info级别，为了不使日志文件占满整个磁盘空间，在记录日志时，要注意避免产生过多的Info级别的日志。

Warn级别

一些警告类的日志可以记录在Warn级别，Warn级别的日志往往说明程序运行异常，不符合预期，但又不影响程序的继续运行，或者是暂时影响，但后续会恢复。像这些日志，就需要你关注起来。Warn更多的是业务级别的警告日志。

Error级别

Error级别的日志告诉我们程序执行出错，这些错误肯定会影响到程序的执行结果，例如请求失败、创建资源失败等。要记录每一个发生错误的日志，避免日后排障过程中这些错误被忽略掉。大部分的错误可以归在Error级别。

Panic级别

Panic级别的日志在实际开发中很少用，通常只在需要错误堆栈，或者不想因为发生严重错误导致程序退出，而采用defer处理错误时使用。

Fatal级别

Fatal是最高级别的日志，这个级别的日志说明问题已经相当严重，严重到程序无法继续运行，通常是系统级的错误。

这里用一张图来总结下，如何选择Debug、Info、Warn、Error、Panic、Fatal这几种日志级别。

如何记录日志内容？

关于如何记录日志内容，我有几条建议：

在记录日志时，不要输出一些敏感信息，例如密码、密钥等。
为了方便调试，通常会在Debug基本记录一些临时日志，这些日志内容可以用一些特殊的字符开头，例如 log.Debugf("XXXXXXXXXXXX-1:Input key was: %s", setKeyName) 。这样，在完成调试后，可以通过查找 XXXXXXXXXXXX 字符串，找到这些临时日志，在commit前删除。
日志内容应该小写字母开头，以英文点号 . 结尾，例如 log.Info("update user function called.") 。
为了提高性能，尽可能使用明确的类型，例如使用 log.Warnf("init datastore: %s", err.Error()) 而非 log.Warnf("init datastore: %v", err) 。
根据需要，日志最好包含两个信息。一个是请求ID（RequestID），是每次请求的唯一ID，便于从海量日志中过滤出某次请求的日志，可以将请求ID放在请求的通用日志字段中。另一个是用户和行为，用于标识谁做了什么。
不要将日志记录在错误的日志级别上。例如，我在项目开发中，经常会发现有同事将正常的日志信息打印在Error级别，将错误的日志信息打印在Info级别。

记录日志的“最佳”实践总结

关于日志记录问题，我从以上三个层面给你讲解了。综合来说，对于日志记录的最佳实践，你在平时都可以注意或进行尝试，我把这些重点放在这里，方便你后续查阅。

开发调试、现网故障排障时，不要遗忘一件事情：根据排障的过程优化日志打印。好的日志，可能不是一次就可以写好的，可以在实际开发测试，还有现网定位问题时，不断优化。但这需要你重视日志，而不是把日志仅仅当成记录信息的一种方式，甚至不知道为什么打印一条Info日志。
打印日志要“不多不少”，避免打印没有作用的日志，也不要遗漏关键的日志信息。最好的信息是，仅凭借这些关键的日志就能定位到问题。
支持动态日志输出，方便线上问题定位。
总是将日志记录在本地文件：通过将日志记录在本地文件，可以和日志中心化平台进行解耦，这样当网络不可用，或者日志中心化平台故障时，仍然能够正常的记录日志。
集中化日志存储处理：因为应用可能包含多个服务，一个服务包含多个实例，为了查看日志方便，最好将这些日志统一存储在同一个日志平台上，例如Elasticsearch，方便集中管理和查看日志。
结构化日志记录：添加一些默认通用的字段到每行日志，方便日志查询和分析。
支持RequestID：使用RequestID串联一次请求的所有日志，这些日志可能分布在不同的组件，不同的机器上。支持RequestID可以大大提高排障的效率，降低排障难度。在一些大型分布式系统中，没有RequestID排障简直就是灾难。
支持动态开关Debug日志：对于定位一些隐藏得比较深的问题，可能需要更多的信息，这时候可能需要打印Debug日志。但现网的日志级别会设置为Info级别，为了获取Debug日志，我们可能会修改日志级别为Debug级别并重启服务，定位完问题后，再修改日志级别为Info级别，然后再重启服务，这种方式不仅麻烦而且还可能会对现网业务造成影响，最好的办法是能够在请求中通过 debug=true 这类参数动态控制某次请求是否开启Debug日志。

拓展内容：分布式日志解决方案（EFK/ELK）

在实际Go项目开发中，为了实现高可用，同一个服务至少需要部署两个实例，通过轮询的负载均衡策略转发请求。另外，一个应用又可能包含多个服务。假设我们的应用包含两个服务，每个服务部署两个实例，如果应用出故障，我们可能需要登陆4（2 x 2）台服务器查看本地的日志文件，定位问题，非常麻烦，会增加故障恢复时间。所以在真实的企业场景中，我们会将这些日志统一收集并展示。

在业界，日志的收集、处理和展示，早已经有了一套十分流行的日志解决方案：EFK（Elasticsearch + Filebeat + Kibana）或者ELK（Elasticsearch + Logstash + Kibana），EFK可以理解为ELK的演进版，把日志收集组件从Logstash替换成了Filebeat。用Filebeat替换Logstash，主要原因是Filebeat更轻量级，占用的资源更少。关于日志处理架构，你可以参考这张图。

通过log包将日志记录在本地文件中（*.log文件），再通过Shipper收集到Kafka中。Shipper可以根据需要灵活选择，常见的Shipper有Logstash Shipper、Flume、Fluentd、Filebeat。其中Filebeat和Logstash Shipper用得最多。Shipper没有直接将日志投递到Logstash indexer，或者Elasticsearch，是因为Kafka能够支持更大的吞吐量，起到削峰填谷的作用。

Kafka中的日志消息会被Logstash indexer消费，处理后投递到Elasticsearch中存储起来。Elasticsearch是实时全文搜索和分析引擎，提供搜集、分析、存储数据三大功能。Elasticsearch中存储的日志，可以通过Kibana提供的图形界面来展示。Kibana是一个基于Web的图形界面，用于搜索、分析和可视化存储在 Elasticsearch中的日志数据。

Logstash负责采集、转换和过滤日志。它支持几乎任何类型的日志，包括系统日志、错误日志和自定义应用程序日志。Logstash又分为Logstash Shipper和Logstash indexer。其中，Logstash Shipper监控并收集日志，并将日志内容发送到Logstash indexer，然后Logstash indexer过滤日志，并将日志提交给Elasticsearch。

总结

记录日志，是应用程序必备的功能。记录日志最大的作用是排障，如果想更好地排障，我们需要一个优秀的工具，日志包。那么如何设计日志包呢？首先我们需要知道日志包的功能，在我看来日志包需要具备以下功能：

基础功能：支持基本的日志信息、支持不同的日志级别、支持自定义配置、支持输出到标准输出和文件。
高级功能：支持多种日志格式、能够按级别分类输出、支持结构化日志、支持日志轮转、具备Hook能力。
可选功能：支持颜色输出、兼容标准库log包、支持输出到不同的位置。

另外，一个日志包还需要支持不同级别的日志，按日志级别优先级从低到高分别是：Trace < Debug < Info < Warn/Warning < Error < Panic < Fatal。其中Debug、Info、Warn、Error、Fatal是比较基础的级别，建议在开发一个日志包时包含这些级别。Trace、Panic是可选的级别。

在我们掌握了日志包的功能之后，就可以设计、开发日志包了。但我们在开发过程中，还需要确保我们的日志包具有比较高的性能、并发安全、支持插件化的能力，并支持日志参数控制。

我还给出了分布式日志解决方案：EFK/ELK。EFK是ELK的升级版，在实际项目开发中，我们可以直接选择EFK。在EFK方案中，通过Filebeat将日志上传到Kafka，Logstash indexer消费Kafka中的日志，并投递到Elasticsearch中存储起来，最后通过Kibana图形界面来查看日志。