后端日志最佳实践

作者: 想54256 | 来源:发表于2021-08-18 14:46 被阅读0次

title: 后端日志最佳实践
Date: 2021/07/27 09:18

什么是日志？

日志是用来记录用户操作、系统运行状态等，是一个系统的重要组成部分。

对于一些简单的应用，可能并不需要在如何记录日志的问题上花费太多精力。

但是对于作为基础平台为很多产品提供服务的后端程序，就必须要考虑如何依靠良好的日志来保证系统可靠的运行了。

你是不是也遇到过这种情况？

1）请求出错时不能通过日志直接来定位问题，而需要开发人员再临时增加日志并要求请求的发送者重新发送同样的请求才能定位问题；

2）无法确定服务中的后台任务是否按照期望执行；

3）无法确定服务的内存数据结构的状态；

4）无法确定服务的异常处理逻辑（如重试）是否正确执行；

5）无法确定服务启动时配置是否正确加载；

在看线上日志的时候，你可曾陷入到这样的日志泥潭？该出现的日志没有，无用的日志一大堆，或者需要的信息分散在各个角落，特别是遇到紧急的在线bug时，有效的日志被大量无意义的日志信息淹没，焦急且无奈地浪费大量精力查询日志。那什么是记录日志的合适时机呢？

什么时候应该打日志？

编程语言提示异常：如今各类主流的编程语言都包括异常机制。这类捕获的异常是系统告知开发人员需要加以关注的，是质量非常高的报错。应当适当记录日志，根据实际结合业务的情况使用warn或者error级别。
与业务流程预期不符：项目代码中结果与期望不符时也是日志场景之一，常见的场景包括：
1. 外部参数不正确
2. 由于参数问题导致查询出的结果不符合规范等。
系统核心角色触发的业务动作 & 组件关键动作：系统中核心角色触发的业务动作也是衡量系统正常运行的重要指标，建议记录INFO级别日志。
1. 电商系统用户从登录到下单的整个流程（对于电商系统而言，用户就是核心角色；对于 ars 系统而言用户也是核心角色，所以他的每个操作还是要记录的）
2. 微服务各服务节点交互
3. 核心数据表增删改
4. 核心组件运行等
5. 注：如果日志频度高或者打印量特别大，可以提炼关键点INFO记录，其余酌情考虑DEBUG级别。
系统初始化：系统或者服务的启动参数。核心模块或者组件初始化过程中往往依赖一些关键配置，根据参数不同会提供不一样的服务。务必在这里记录INFO日志，打印出参数以及启动完成态服务表述。

其他的还有：

请求的入口和出口（也可以做一些统计的操作，例如：用户IP、上传下载的数据量、请求耗时等）
外部服务的调用和返回
资源消耗操作，例如读写文件
程序异常，例如数据库无法连接
后台操作，例如定时执行任务的线程
启动、关闭、配置加载
审计日志
- 对涉及到重要的信息进行记录。
- 审计主要体现在安全上，可以发现非授权的操作。

日志应该怎么打？

基本格式

日志时间
日志级别主要使用
调用链标识（可选）
线程名称
日志记录器名称
日志内容
异常堆栈（不一定有）

11:44:44.827 WARN [93ef3E0120160803114444] [main] [ClassPathXmlApplicationContext] Exception encountered during context initialization - cancelling refresh attempt

日志级别

ERROR：ERROR = 报警 = 某个功能彻底不可用，比如，数据库连接异常（需要运维人员立刻修复）、业务功能受损（即系统的关键业务流程走不下去了，比如：淘宝收货地址服务宕机导致用户无法修改收货地址）等情况。这种日志出现之后要求立刻处理。一般不能随便的打印 error 日志。在输出 ERROR 级别的日志时，尽量多地输出方法入参数、方法执行过程中产生的对象等数据（toString not json）。
WARN：WARN 级别的主要输出警告性质的内容，这些内容是可以预知且是有规划的，比如：用户输入参数错误、接口响应时间过长等。在 WARN 级别的时应输出较为详尽的信息，以便于事后对日志进行分析。WARN代表可恢复的异常，此次失败不影响下次业务的执行。
INFO：INFO 级别日志记录的是在正常运行状态下系统的关键信息，旨在保留系统正常工作期间关键运行指标。开发可以将初始化系统配置、业务状态变化信息，或者用户业务流程中的核心处理记录到 INFO 日志中，方便日常运维工作以及错误回溯时上下文场景复现。
DEBUG：DEBUG 级别主要输出调试性质的内容，该级别日志主要用于在开发、测试阶段输出。该级别的日志应尽可能地详尽，开发人员可以将各类详细信息记录到DEBUG里，起到调试的作用，包括参数信息，调试细节信息，返回值信息，Mybatis 执行的 SQL（最好在打印前判断下日志级别，否则字符串拼接还是挺费内存的）等等。

小练习

---- ERROR

模型连接超时

调用模型时传入的参数格式不正确

---- WARN

调用模型时传入的参数值有误

---- INFO

XX 用户启动机器审查

重试

---- DEBUG

调用模型的请求参数

模型响应的结果

请求的用户信息

考虑日志使用者

打印日志时要考虑日志的使用者，我们的日志的使用者主要是开发和运维人员，所以打印的日志最好是两者都能看懂的（有的时候能让运维人员解决，就别让他们找我们）：

2021-07-23 14:28:38.103  ERROR [           main] com.dist.Demo : 获取任务实例code请求失败

这种日志，开发可能会看懂，但是运维人员看到可能就会一头雾水，只能在去找开发。所以至少应该是：

# 此处使用 ERROR 级别的日志是因为模型连接超时，可能是由于模型服务挂掉了
# 记录案发现场信息 + 堆栈信息
2021-07-23 14:28:38.103  ERROR [           main] com.dist.Demo : 调用模型接口「http://example.com/」时由于「连接超时」导致获取任务实例 code 失败。请求方法为「POST」，请求参数为：「{name = zs}」
... 异常堆栈

这样运维人员一眼就能清楚问题的原因（可能是模型挂了），而不用在找开发来确定问题。

不记录无用的日志

1）能够放在一条日志里的东西，放在多条日志中输出；

2）预期会发生且能够被正常处理的异常，打印出一堆无用的堆栈；

3）开发人员在开发过程中为了调试方便而加入的“临时”日志

日志打印注意点

记录异常处理逻辑，例如：
1. 对于分布式存储系统，当系统从一个存储节点上读数据失败时，需要去另一个数据节点上进行重试，可以将读数据失败这件事情记录下来，之后可以通过对日志的分析确认是否某些节点的磁盘可能存在故障。
2. 如果系统需要请求一个外部资源，可以将请求这个外部资源偶尔失败又重试成功这件事情记录下来，具体来说：
```
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) timeout ... 1 try
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) timeout ... 2 try
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) success
```
要好于
```
[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth request (to http://auth1.example.com/v2) success
```
因为前者可以让我们预判被依赖的服务器服务质量有风险，也许需要进行扩容；

对于 trace/debug/info 级别的日志输出，必须进行日志级别的开关判断。

// 虽然在 debug(参数)的方法体内第一行代码 isDisabled(Level.DEBUG_INT)为真时，就直接 return，但是参数可能会进行字符串拼接运算。此外，如果 debug(getName()) 这种参数内有 getName()方法调用，无谓浪费方法调用的开销。
// 如果判断为真，那么可以输出 trace 和 debug 级别的日志
if (logger.isDebugEnabled()) {
logger.debug("Current ID is: {} and name is: {}", id, getName());
}

为避免重复打印日志，浪费磁盘空间，请关闭 additivity
```
<logger name="com.taobao.dubbo.config" additivity="false">
```

异常信息应该包括两类信息：案发现场信息和异常堆栈信息。

log.error(e.getMessage());//错误示范
log.erroe("Bad Things",e.getMessage());//错误示范
log.error("Bad Things",e);//正确演示

日志打印时禁止直接用 JSON 工具将对象转换成 String。如果对象里某些get方法被重写，存在抛出异常的情况，则可能会因为打印日志而影响正常业务流程的执行。打印日志时仅打印出业务相关属性值或者调用其对象的 toString() 法。
不允许使用标准输出

包括System.out.println()和System.error.println()语句。因为这个只会打印到控制台，而不会记录到日志文件中，不方便管理日志。

不允许使用 e.printStackTrace()，因为他使用的也是标准错误输出。

注：我们其实平时抛出的异常实际上也是输出到了标准错误输出中，但是 SpringMVC 和 Dubbo 都有异常拦截器，将这些异常拦截掉（try-catch）之后通过日志框架再进行打印。
如果 INFO 级别日志数量过于庞大，考虑将日志级别调整为 DEBUG。
可以使用 warn 日志级别来记录用户输入参数错误的情况，避免用户投诉时，无所适从。如非必要，请不要在此场景打出 error 级别，避免频繁报警。
注意日志输出的级别，error 级别只记录系统逻辑出错、异常或者重要的错误信息。
例如根据用户传入的 id 查询一个数据，如果查询不到，是否应该抛出异常，抛出异常这个动作太重了，但不通过异常由没法结束整个调用链路，那么怎么办呢？
1. 太重
2. error 代表着报警，需要运维处理。
  
  So，我们可以自定义 dubbo、spring 拦截器，拦截这些自定义异常，打印 warn 级别日志。

小技巧

动态 DEBUG 日志输出

DEBUG日志和INFO日志的一个重要的区别是，INFO 日志用于记录常规的系统运行状态（业务状态变化信息、用户业务流程中的核心处理记录等），对于定位一般的问题已经足够了。而 DEBUG 日志则详细的记录了一个请求的处理过程，甚至是每一个函数的输入和输出结果，遇到一些隐藏比较深的问题时，必须要依赖DEBUG日志。

然而，由于 DEBUG 级别的日志数量比INFO级别的数量多很多（通常差一个数量级），如果长期在线上服务器开启 DEBUG 级别的日志输出，日志量太大。再比如，有时候仅仅是由于某一个用户的访问模式比较特殊导致了问题，如果将整个服务（特别是一个服务部署了很多台节点时）都临时调整为 DEBUG 级别日志输出，也非常不方便。

所以可以采用这种方案：当接收到的HTTP请求的QueryString中包含DEBUG=true参数时，就将所有的DEBUG级别的日志也输出。

慢操作日志

服务在接收到一个请求的时候，记录请求的接收时间（T1），在请求处理完成待发送的时候，会记录请求发送时间（T2），通常一个请求的日志都记为INFO级别，然而当出现请求处理时间（T2-T1）超过一定时间（如10s）时，可以将该日志提升为WARN级别。通过该方法，可以预先发现系统可能存在的一些问题。

同样的慢操作日志还可以用来记录系统一些外部依赖的处理时间，如一个服务可能依赖外部认证服务器来进行认证授权。通过记录每次认证请求的时间并将超出预期时间的请求日志采用WARN级别输出，可以尽早发现认证服务器是不是需要扩容等问题。

慢日志的时间阈值应该是可以动态调整的，这样在进行系统优化时，可以将该报警时间阈值逐渐调小，不断地对系统进行优化。

Error 级别日志报警

上面在讲日志级别的时候说过 ERROR 级别代表着系统某个地方出现了问题需要运维人员来处理，那么一般我们都会采用邮件通知的方式进行报警，Logback 也为我们提供了这样的一个 Appender —— SMTPAppender。

具体使用参见下面两篇文章：

日志监控报警注意事项：

能不报警的就不报警，只有需要运维马上处理的错误才需要发送报警。这样做的原因是避免长期的报警骚扰让运维人员对报警不再敏感，最后真的报警来了时，变成了狼来了的传说；

明确报警关键字，例如用 ERROR 作为报警的关键字，而不是各种各样的复杂规则。这样做的原因是日志监控本质上是不断的进行字符串匹配操作，如果规则太多太复杂，就可能对线上服务产生影响；

对于一些预警操作，例如某个服务需要重试多次才能成功，或者某个用户的配额快用完等等，可以通过每天一封报警邮件的方式来反馈；

每一次系统出现故障，都需要及时检查日志报警是否灵敏，日志报警的描述是否准确等，不断优化日志报警；

ERROR、WARN 级别日志打印包名和行号

ERROR & WARN 日志都代表着系统出现了问题，需要解决；但有时仅仅凭借着一行日志并不能很快的定位到问题，所以可以考虑将打印 ERROR、WARN 日志的包名和行号打印出来。

logback 并没有提供这种功能，不过我们可以通过自定义 Layout 来实现。

DEV 环境不向本地输出日志文件

开发环境是用于开发本地调试时使用，一般都只需要看控制台就可以，所以没必要在本地输出日志文件，那么我们可以利用 logback 的“条件表达式”来实现：

<!-- 注：当环境为 dev 时，将日志文件输出至系统缓存文件夹 -->
<if condition='property("PROFILES_ACTIVE").contains("dev")'>
    <then>
        <springProperty scope="context" name="LOG_PATH" source="logging.path"
                        defaultValue="../DEFAULT_LOG_PATH/${APPLICATION_NAME}/${PROFILES_ACTIVE}"/>
    </then>
    <else>
        <springProperty scope="context" name="LOG_PATH" source="logging.path"
                        defaultValue="../DEFAULT_LOG_PATH/${APPLICATION_NAME}/${PROFILES_ACTIVE}"/>
    </else>
</if>

日志输出到不同的文件

在性能测试时遇到的另一个问题是，当并发量很大时，可能会有一些请求处理失败（如0.5%），为了对这些错误进行分析，需要去查这些错误请求的日志。而由于这种情况下日志量巨大，使得对错误日志的分析变得困难。

这种情况下可以将所有的错误日志（ERROR）同时输出到一个单独的文件之中。

我现在是整了 3 个日志文件：

all.log - 存储所有级别的日志

warn.log - 单独存储 warn 级别日志

error.log - 单独存储 error 级别日志

日志文件大小

日志文件不宜过大，过大的日志文件对于日志监控，问题定位等都会带来不便。因此需要进行日志文件的切分，日志文件应该按天来分割，还是按照小时来分割，应该根据日志量来决定，原则就是方便开发或运维人员能快速查找日志。

logback 日志工具可以在日志文件滚动后将前一文件进行压缩，以减少磁盘空间占用，若使用 logback 对于日志量庞大的应用建议开启该功能。

为了防止日志文件将整个磁盘空间占满，需要定期对日志文件进行删除。例如，在收到磁盘报警时，可以将两个月以前的日志文件删除。

生产环境中的文件输出，可以考虑使用异步文件输出，该种方式日志并不会马上刷新到文件中去，会产生日志延时，在停止应用时可能会导致一些还在内存中的日志未能及时刷新到文件中去而产生丢失，如果对于应用的要求并不是非常高的话，可考虑异步日志

链路追踪

本部分只介绍 zipkin

Zipkin 是一款开源的分布式实时数据追踪系统，主要功能是聚集来自各个异构系统的实时监控数据，和微服务架构下的接口直接的调用链路和系统延时问题。

总结一下链路追踪工具主要提供了以下功能：

将一次请求所涉及到的链路串联起来，这个请求并非特指 http 请求，也可以是其他（redis、rpc）请求
定位整个链路的延时问题，通过这个来动态调整应用实例数量。

所以其实没有必要所有的请求的链路都上传到 zipkin，zipkin 为我们提供了一个采样率的概念：

CountingSampler 计数采集，每多少次请求才收集一个，比如说30个请求之后，再收集一个。
BoundarySampler 概率采集，最小值是0.0001，最大是1，0表示从来不采集。
RateLimitingSampler 限速采集，比如说限制秒钟最多采集10个，就可以用这个。

总结

以下情况下需要打日志：
- 编程语言提示异常（但一般框架会有异常拦截器拦截进行异常的打印），因为不打印进日志只会在控制台中看到。
- 程序异常，例如数据库无法连接（ERROR）
- 输入参数不正确（WARN）
- 查询出数据不正确（根据情况选择 WARN 或 ERROR）
- 核心角色触发的业务动作（INFO）
- 核心数据表的增删改（INFO）
- 核心组件的运行（INFO）
- 请求的入口和出口、外部服务的调用和返回（根据情况选择 DEBUG 或 INFO）
- 资源消耗操作，例如读写文件（DEBUG）
- 后台操作，例如定时执行任务的线程（根据情况选择 DEBUG 或 INFO）
- 启动、关闭、配置加载（INFO）
注：如果日志频度高或者打印量特别大，可以提炼关键点INFO记录，其余酌情考虑DEBUG级别。
日志级别
- ERROR：系统中某个功能彻底不可用（比如数据库异常、数据库中数据有问题等），需要运维人员立刻处理。
- WARN：WARN 代表可恢复的异常，此次失败不影响下次业务的执行（比如：用户输入参数错误、接口响应时间过长）
- INFO：正常运行状态下系统关键信息（比如：初始化系统配置、业务状态变化信息，或者用户业务流程中的核心处理记录）。
- DEBUG：调试性质的内容，该级别日志主要用于在开发、测试阶段输出，该级别的日志应尽可能地详尽（比如：参数信息，调试细节信息，返回值信息）。
考虑日志的使用者，日志要包括案发现场信息和异常堆栈信息，尽量让运维人员能够通过日志排查一部分问题。
记录一些异常逻辑，比如：重试过程中日志的记录。
对于 trace/debug/info 级别的日志输出，必须进行日志级别的开关判断。
打印时禁止使用 Json 序列化对象，使用对象的 toString() 方法。

最重要的还是不断优化日志。

不断优化日志

有一点可以肯定，好的日志就像好的文章一样，绝不是一遍就可以写好的，而需要在实际的运维过程中，结合线上问题的定位，不断地进行优化。

此处有以下几个比较好的实践：

在定位问题的过程中完善日志，如果定位问题花费了很长时间，那就说明系统日志还存在问题，需要进一步完善和优化；
需要思考是否可以通过优化日志，来提前预判该问题是否可能发生（如某种资源耗尽而导致的错误，可以对资源的使用情况进行记录）
定义好整个团队记录日志的规范，保证每个开发记录的日志格式统一；特别需要说明的是，对于DEBUG/TRACE级别的日志，也需要定义好清晰的格式，而不是由开发人员自由发挥；
整个团队（包括开发，运维和测试）定期对记录的日志内容进行Review；
运维或测试在日志中发现的问题，都需要及时向开发人员反映；

参考文档

Java日志记录最佳实践

最佳日志实践（v2.0）

其他 TODO

1）链路追踪

image-20210727103129327

image-20210727103647756

2）访问日志

image-20210727165517916

3）Swagger 页面动态切换用户或者使用 chrome 插件实现（不推荐，因为还要安装，java 浏览器版就是这样没火起来的）

image

或者插件。可以记住的。点击切换用户（cookie），时间要比一般的长

4）其他

logback 的原理

root 和 logger 的继承

5）规范

不能用父类的logger 对象

image-20210813145443340