本文主要介绍如何写一个好的日志

1. 日志编写位置

日志编写的位置可以说是重中之重，好的日志位置可以帮你解决问题，也可以让你更加了解代码的运行情况。

系统/应用启动和参数变更：当系统启动时，可以将相关的参数信息进行打印，以便出现问题时，更准确地查询原因；参数信息可能并不存储在本地，需要通过配置中心获取，而参数信息有变更时，也需要将变更后的内容输出在日志中。
关键操作节点：最典型的就是在关键位置添加日志，记录用户进行的某个操作。当出现问题时，你可以通过这个位置的日志了解到用户的操作。同样你也可以在系统进行某些操作时添加日志，比如你准备启动某个线程池来进行数据处理时，可以加上日志便于以后分析问题。
大型任务进度上报：当系统在处理某个比较大型的任务时，可以在这个过程中增加相关的日志来表明任务处理的进度，防止因为长时间没有处理而无法得知程序执行的状态，比如在文件下载时，可以按照百分比来定时/定次地上报数据。
异常：当程序出现异常时，我们通常是通过 try-catch 来记录当时的情况，然后以日志的形式表现出来。如果是通过 try-catch 处理，你需要注意日志编写的位置。如果你需要将日志在本层抛出，则不需要进行日志记录，否则会出现日志重复的问题。如果你除了异常以外还需要记录其他的内容，则可以通过定制异常信息来实现。

2. 写入性能

日志的写入性能则会受到如下 5 个因素的影响：

日志编写位置：日志编写的位置在程序中十分重要，如果在 for 循环中编写，因为这个循环会持续很多次，那么就会产生大量的日志记录。此时可以考虑一下，这个日志的记录是否有必要。
日志数量：如果你大量地编写日志，那么日志的质量一定会降低。同时，大量的日志会让你很难去查看问题，反而成了一种负担。在高访问量时，过多的日志也会影响程序的执行效率。
日志编写等级：我在上一节中讲过，日志等级很容易被滥用，不正确的日志等级会导致我们查询问题的时间增加。
日志输出级别：这里指的是对于配置日志输出级别的选择。在线上环境，不建议使用 debug 级别，因为线上一直有请求，debug 级别会输出大量的基础和请求信息，极其浪费资源，因此建议开启 info 或者以上。
无用输出参数：不对大字段、无用字段输出，因为这很影响程序执行效率和日志的内容。我曾遇到一个案例，A 同学在线上打印了一个完整的 HTML 内容，导致当日的部分日志内容错乱，部分日志无法检索，原因就在于 HTML 存在多行内容导致无法解析的问题。当开发人员到线上服务器上查看时，日志文件的大小已经扩大了 3 倍。

好的日志一定是便于你去排查问题的。在编写日志时你一定要思考这个日志可以帮你做什么。

3. 占位符

在日志编写时尽可能地选择基于占位符的编写方式，这样做的好处是

节约性能。在生成较高级别的日志时，低级别的日志会不停叠加字符串而占用过多的内存、CPU 资源，导致性能浪费。
便于编写。先确认日志所想要表达的内容，再确认你所需要编写的参数，这样在写日志时，目的也会更加明确。
便于查看。在代码 review 时，更方便查看日志想表达的意思，而不会被日志的参数打乱。

4. 可读性

日志的可读性也是日志编写的关键之一。一个好的日志就像一篇好的文章，能让你很快了解到这个日志中的关键信息。

级别，例如 warn、info 和 error
时间
进程ID
线程ID：线程ID相当重要，在解决多线程问题的时候，这一项信息是必不可少的
模块：哪个类，假如是分布式服务的话，需要指明是哪个服务的哪个类
Filter：主要用于查找某一类LOG时候方便，这个Filter是开发人员在开发过程中自己定义的，可以是方法名/业务模块名称/功能名称等等。
请求id（traceId）: 一个请求到来会经过很多服务的很多方法，一个唯一的请求id可以将该请求的所有日志串联起来。一般我们会配合链路追踪系统一同使用，因为后者可以实现跨应用的日志追踪，从而帮助我们过滤掉不相关的信息。
调用层级标识（spanId）：调用层级标识
耗时：可以通过拦截器或AOP来打印某服务或某核心方法的耗时，可以使用一些agent来拦截方法执行时间。
会话标识：当前操作的用户和与当前请求相关的信息，能知道是哪个客户端或者是哪个用户触发，类似 Session。当出现问题/查看行为时，可以根据这个值来快速识别到相关的日志。
入参出参：入参和出参不是每个地方都要打印的，只在服务对外暴露的API/核心方法提供即可。注意打印的参数一定要是原始参数，而不是经过转换后的参数，防止你参数转换的代码有问题。
场景信息（谁，什么功能等
状态信息(开始，中断，结束)以及重要参数
日志格式：日志格式统一使用主语+谓语+宾语+状语的格式，日志打印应该遵从人类的自然语言，任何没有开发经验或是外行人都能从你的日志中捕获到有用的信息。使用 [] 进行参数变量隔离，这样的格式写法，可读性更好，对于排查问题更有帮助

5. 关键信息隐蔽

对于关键的信息不显示或者进行掩码显示，以免信息被盗取后出现数据内容泄漏。

6. 减少代码位置信息的输出

如果不是必要，尽量不要在日志格式中输出当前日志所在的代码行和方法名称信息。如果你看过 logback，log4j 的源码你就知道，这都是通过获取当前线程堆栈快照信息来进行实现的，这种实现方式会极大地影响程序执行的效率。

在 log4j 的文档中有这样一段话：“使用同步方式进行获取位置信息会慢 1.3 到 5 倍，如果是使用异步日志，因为会涉及跨线程获取位置信息，会慢 30 到 100 倍。

所以，关闭代码位置信息的输出可以节省系统资源的使用，提升性能。

7. 文件分类

文件分类可以帮助你提高检索日志信息时的效率。将不同的业务逻辑按照不同的日志文件来分类，可以保证你看到的信息都是和这个功能相关的，不会被其他的日志干扰。这也是在大型系统中经常会使用到的功能。

可以根据不同日志级别，或不同业务来命名，便于排查。命名时需要注意：见名知意。如 appName_logType_logName.log。logType:日志类型，推荐分类有 stats/desc/monitor/visit 等；logName:日志描述。这种命名的好处：通过文件名就可知道日志文件属于什么应用，什么类型，什么目的，也有利于归类查找。

8. 日志格式

系统之间格式保持一致：每个应用在日志格式上尽量保持统一，这样，运维人员在进行日志收集时，就可以采用统一的日志模板来收集和格式化内容，减少双方的沟通成本。

不编写多行的日志内容：除了异常堆栈信息，不对日志内容进行多行的输出，多行的内容十分不便于数据解析，可能会出现生成多条日志的情况。

不要使用日志中的常见内容来分割：如果采用日志中常见的内容来分割，会在格式解析时出现问题，比如用户 ID 中的空格就是比较常见的内容。

一个日志格式示例

2019-12-01 00:00:00.000|pid|log-level|[service-name,trace-id,span-id,user-id,biz-id]|thread-name|package-name.class-name : log message

我们也可以将日志格式分为普通日志和特定格式日志

普通日志前缀是固定的，可以固定分词索引，方便更快的查询分析。

2019-11-26 15:01:03.332|1543|INFO|[example-server-book-service,28f019d57b8336ab,630697c7f34ca4fa,105,45982043|XNIO-1 task-42]|c.p.f.w.pay.PayServiceImpl     : order is paying with userId: [105] and orderId: [45982043]

特定格式日志，以 access 日志为例：

2019-11-26 15:01:03.332|1543|INFO|[example-server-book-service,28f019d57b8336ab,630697c7f34ca4fa,105,45982043|XNIO-1 task-42]|c.p.f.w.logging.AccessLoggingFilter     :
> url: http://liweichao.com:10011/actuator/health
> http-method: GET
> request-header: [Accept:"text/plain, text/*, */*", Connection:"close", User-Agent:"Consul Health Check", Host:"liweichao.com:10011", Accept-Encoding:"gzip"]
> request-time: 2019-11-26 15:01:03.309
> querystring: -
> payload: -
> extra-param: -


< response-time: 2019-11-26 15:01:03.332
< take-time: 23
< http-status: 200
< response-header: [content-type:"application/vnd.spring-boot.actuator.v2+json;charset=UTF-8", content-size:"15"]
< response-data: {"status":"UP"}

特定格式日志可按格式创建索引更方便聚焦查询分析和告警，如根据 take-time，http-status，biz-code 等值。

9. 一些错误写法

参数变量隔离

// 反例
logger.debug("Processing trade with id: " + id + " symbol: " + symbol);
// 正例
logger.debug("Processing trade with id:[{}] and symbol : [{}] ", id, symbol);

如果进行了抛出异常操作，请不要记录error日志

// 反例
try{
    ....
}catch(Exception ex){
  String errorMessage=String.format("Error while reading information of user [%s]",userName);
  logger.error(errorMessage,ex);
  throw new UserServiceException(errorMessage,ex);
}

// 正例
try{
    ....
}catch(Exception ex){
  String errorMessage=String.format("Error while reading information of user [%s]",userName);
  throw new UserServiceException(errorMessage,ex);
}

优化DEBUG

// 优化前
//1. 获取用户基本薪资

//2. 获取用户休假情况

//3. 计算用户应得薪资

// 优化后
logger.debug("开始获取员工[{}] [{}]年基本薪资",employee,year);

logger.debug("获取员工[{}] [{}]年的基本薪资为[{}]",employee,year,basicSalary);
logger.debug("开始获取员工[{}] [{}]年[{}]月休假情况",employee,year,month);

logger.debug("员工[{}][{}]年[{}]月年假/病假/事假为[{}]/[{}]/[{}]",employee,year,month,annualLeaveDays,sickLeaveDays,noPayLeaveDays);
logger.debug("开始计算员工[{}][{}]年[{}]月应得薪资",employee,year,month);

logger.debug("员工[{}] [{}]年[{}]月应得薪资为[{}]",employee,year,month,actualSalary);

10. 参考资料

《分布式链路追踪实战》

https://mp.weixin.qq.com/s/AoNW–AjaelatnHxuWt5WQ

日志（2）- 日志写法

最后更新：2020-10-16