如何正确地打日志

在程序中打日志很简单，logger.debug("Hello, Happy World!")，OK。可是，正确地打日志并不简单，需要注意以下几个问题。

日志的目的

备注：本文中的“日志”专指程序内部日志。

打日志是为了记录程序的运行情况，这样可以：

• 确认事件发生顺序、时间节点
• 记录问题，便于在系统发生异常时定位问题、解决问题。
• 在多线程、集群等复杂环境中，利用日志分析时序
• 监控某些程序的状态
• ……

因此，日志要记好有助于解决问题的各类信息，不要堆积无助于解决问题的垃圾，而且要遵循一定的规范，便于查找、定位。

在这里向没有开发经验的人强调一下：生产系统的日志量非常大，而且出于性能考虑不会展示调试日志。在海量日志中找信息是件很麻烦的事情，请不要给维护人员挖坑。

日志的内容

通过日志，应该能快速地了解“什么时间在哪里大概发生了什么事”，猜到“大概是什么原因导致了问题”，然后进一步定位程序代码，确认问题、解决问题。例如：

2020-01-02 12:34:56 [UserService] WARN 查询用户不存在，uid = 1234567890
2020-01-03 12:45:06 [AuthService] INFO 实名核验成功，uid = 1234567899，身份证号 = 110101123412341234，耗时 = 12ms
2020-01-04 12:56:01 [InfoService] ERROR 用户保存个人信息时发生异常
java.sql.SQLException: ORA-12899: value too large for column "XXXXX"."YYYYY"."ZZZZZ" (actual: 60, maximum: 30)
        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:445)
        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:396)
        ......

一条日志应该包含以下内容：

• 时间（“何时”）：日志要记录事件的发生时间。
  • 日志组件记录的实际上是“打日志的时间”，而非“事件发生时间”。不过，通常事件执行时间很短，这个差异可以忽略不计。
  • 如果事件执行时间比较长，“时间”就要区分为“发生时间”、“结束时间”和“持续时间”。
• 具体位置（“何地”）：记录事件于哪个模块、文件、函数等产生。建议至少把模块名打上，以便翻代码。
• 事件简要描述（“什么事情”）：看到日志之后大概能猜到发生了什么事情。语言要简洁。
  • 不好的例子：“发生错误”、“数据库异常”、“数据不存在”
  • 好的例子：“查询用户信息时产生异常”、“执行用户信息保存时数据库异常”、“用户id不存在”
  • 建议描述文字不要完全相同。比方说，都是“数据查询失败”，其中一处可以写成“数据查询失败了”，而另一处写成“数据查询的失败”，这样便于直接使用全文搜索功能查代码。
• 日志等级：把日志等级写好，出问题时就可以根据问题的严重性来找日志。
• 上下文：例如
  • 异常的堆栈
  • 重要参数：有时需要复现问题，可以记录某些重要参数（例如uid）以便还原现场
  • 重要状态变化：例如线程启动/中断、特殊进程进入/退出等

在开发时要用团队封装好的框架，不要自己造轮子。

日志的等级

以Java为例，Java日志通常分为ERROR、WARN、INFO、DEBUG和TRACE。其他语言和框架情况类似。

这几个级别用法通常如下：

• ERROR：记录影响系统与业务的严重问题，例如系统异常、数据库故障等。
• WARN：记录“确实是问题，不过不耽误使用”的问题，以便后续跟踪检查。
• INFO：比较重要的信息，例如系统参数、线程启动/结束、特殊任务等。
• DEBUG、TRACE：记录开发调试过程中的细节。这类信息只要能方便开发人员调试即可。在生产环境中，这类信息应该被屏蔽掉，不往日志里头打，或者仅在跟踪问题时临时启用，用完之后立刻关掉。

打日志的位置

假设信息查询的堆栈如下：

QueryController.queryInfo()
    UserService.getUserInfo()
        UserDAO.getUser()
        RoleDAO.getRole()
    InfoService.getInformation()
        InfoDAO.getInfo()
    InfoCommonMethod.generateOutput()

捕获异常、输出异常日志的操作尽量都交给最外层的调用方，即上面的QueryController.queryInfo()。

里层的函数（UserService.getUserInfo()、UserDAO.getUser()等）在抛出异常时不要打日志。否则里面打一遍，外面打一遍，日志就重复了。

像下面这样写函数就是在坑人：

public String getUser(String param ...) throws IOException {
    try {
        // 业务逻辑
        ...
    } catch (IOException e) {
        logger.error("错误", e);
    } finally {
        // 清理
        ...
    }
}

以上代码存在三个问题： 1. 发生异常时，异常直接catch掉，未往上抛（throw e;），导致调用者无法捕获异常。 2. 在此处打日志，调用者捕获异常之后还要打日志，日志信息就重复了。 3. 如使用数据库事务（例如Spring的@Transactional），那么将无法正确回滚，导致状态错误。

日志文件

不要假设日志全部都会输出到屏幕上，或者全部输出到特定的日志文件中！

日志输出目标是可以调整的，例如直接输出到stdout/stderr（生产环境不会这样干）、输出到特定日志文件、输出到数据库，或输出到特定的日志服务器中。日志不仅可以输出到单个文件，也可以根据子系统、日志级别、日志目的、日期时间等条件将日志拆分成多个文件。

因此要杜绝用System.out.println()、System.error.println()与e.printStackTrace()打日志！这样打出来的日志，不仅缺乏信息，而且有可能会打错地方，让人找不到。

第三方接口务必要打日志，而且不仅要记一些关键参数，还要便于查询（例如放入专门的XX公司接口日志文件中），以免出问题时互相踢皮球。

其他的坑

• catch里面不要空着。遇到异常时，如果不处理，不上抛，也不打日志，一旦出现问题，就把大家全都坑了。
• 不要只输出e.getMesssage()，要输出整个堆栈，否则难以定位。
• 不要把详细信息（特别是堆栈）暴露给用户。
• 再强调一遍，不要System.out.println()、System.error.println()与e.printStackTrace()。这样打，不仅缺乏信息，而且有可能会打错地方，让人找不到。
• 生产环境不要打DEBUG日志，否则影响性能。生产系统部署时，应通过配置文件或开关调整日志等级，把DEBUG日志屏蔽掉。
  • 系统刚上线时，为了便于调整，可能也会把DEBUG日志打出来。此时要留意服务器磁盘空间，别让日志把磁盘撑爆。
• 日志是各线程公用的。需要换行的话，要先使用\n拼接字符串，拼好之后一口气打出来。多次执行打日志语句，日志内容可能会被其他业务打断。
• 频繁执行的代码、数据量大的数据要尽量避免打调试日志，同样影响性能。

补充：一种便于诊断的方案

仅在后台打日志，实际上不便于问题定位诊断，而直接把细节打到前台，虽然方便定位了，但不仅对用户不友好，还会引发安全风险。所以可以稍微变通一下：

• 设计一套错误编码，例如：I-1A2B-7F-03，I指IOException，1A2B是class名字经过hash之后取前四位，7F是行号转为十六进制，03是个随机数。
• 在系统发生异常时，除了错误信息，把这个编码打到前台页面与后台日志中，并要求用户反馈异常时提供这个代号。
• 因为这个编码是很独特的，所以翻日志的时候直接搜这个编号就能比较容易地定位。即使不找日志，通过“1A2B”和“7F”两个代码也可以反查到是哪个class与哪一行代码了。