最佳日志实践（v2.0）

0. 缘起

大约在三年前，我曾经写过一篇最佳日志实践，还被码农周刊选为那年的最受欢迎技术干货之一。当时我任职于网易杭州研究院的存储平台组，主要做网易对象存储（NOS）的开发和部分运维工作。由于网易云音乐，易信等几个重要产品陆续上线，业务压力剧增，我们的系统在前前后后大约半年的时间里，出现了大大小小各种事故。通过不断总结事故原因、不断地优化代码、进化部署架构，才使整个系统逐渐稳定下来。那个时候组里人常常开玩笑说，我们采用的是TDD的开发模式，只是这个TDD不是测试驱动开发（Test Driven Development），而是悲剧驱动开发（Tragedy Driven Development）。

最佳日志实践的第一版便是在那个时候完成的，里面包含了我们在开发和运维过程中的一些好的实践。最初起名 “最佳日志实践” 实在有些标题党，不过由于起名字是一件比写代码更困难的事儿，我就继续沿用这个名字吧。有几个原因让我一直想要对那篇文章进行整理和扩充：

那篇文章里的一些内容太细节，涉及到了网易对象存储中的业务逻辑，对读者不够友好；
那篇文章里一些内容基于Java语言来讨论，实际上之后我有很多的精力都在基于Go语言做开发，因此现在更想要讨论一些与语言无关的方面；
最近几年又写了若干个系统，对于日志这件事情又有了一些心得和体会，也想拿来跟大家分享；

开始正文吧...

1. 什么是日志

日志用来记录用户操作、系统运行状态等，是一个系统的重要组成部分。然而，由于日志通常不属于系统的核心功能，所以常常不被团队成员所重视。对于一些简单的小程序，可能并不需要在如何记录日志的问题上花费太多精力。但是对于作为基础平台为很多产品提供服务的后端程序，就必须要考虑如何依靠良好的日志来保证系统可靠的运行了。

好的日志可以帮助系统的开发和运维人员：

了解线上系统的运行状态
快速准确定位线上问题
发现系统瓶颈
预警系统潜在风险
挖掘产品最大价值
……

不好的日志导致：

对系统的运行状态一知半解，甚至一无所知
系统出现问题无法定位，或者需要花费巨大的时间和精力
无法发现系统瓶颈，不知优化从何做起
无法基于日志对系统运行过程中的错误和潜在风险进行监控和报警
对挖掘用户行为和提升产品价值毫无帮助
……

2. 日志的分类

日志从功能来说，可分为诊断日志、统计日志、审计日志。

诊断日志，典型的有：

请求入口和出口
外部服务调用和返回
资源消耗操作: 如读写文件等
容错行为：如云硬盘的副本修复操作
程序异常：如数据库无法连接
后台操作：定期执行删除的线程
启动、关闭、配置加载

统计日志：

用户访问统计：用户IP、上传下载的数据量，请求耗时等
计费日志（如记录用户使用的网络资源或磁盘占用，格式较为严格，便于统计）

审计日志：

管理操作

对于简单的系统，可以将所有的日志输出到同一个日志文件中，并通过不同的关键字进行区分。而对于复杂的系统，将不同需求的日志输出到不同的日志文件中是必要的，通过对不同类型的文件采用不同的日志格式（例如对于计费日志可以直接输出为Json格式），可以方便接入其他的子系统。

3. 日志中记录什么

理想的日志中应该记录 不多不少 的信息。

所谓不多，是指不要在日志中记录无用的信息。实践中常见到的无用的日志有：1）能够放在一条日志里的东西，放在多条日志中输出；2）预期会发生且能够被正常处理的异常，打印出一堆无用的堆栈；3）开发人员在开发过程中为了调试方便而加入的“临时”日志

所谓不少，是指对于日志的使用者，能够从日志中得到所有需要的信息。在实践中经常发生日志不够的情况，例如：1）请求出错时不能通过日志直接来定位问题，而需要开发人员再临时增加日志并要求请求的发送者重新发送同样的请求才能定位问题；2）无法确定服务中的后台任务是否按照期望执行；3）无法确定服务的内存数据结构的状态；4）无法确定服务的异常处理逻辑（如重试）是否正确执行；5）无法确定服务启动时配置是否正确加载；6）等等等等

输出日志时要考虑日志的使用者，例如如果日志主要由系统的运维人员来看，那就不能输出：

[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, ErrorCode:1426

至少应该是：

[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, ErrorCode:1426, Message: callback request (to http://example.com/callback) failed due to socket timeout

这样运维人员一眼就能清楚问题的原因，而不需要再通过开发来查看ErrorCode对应的具体错误。

整理一下通常情况下会遗漏的日志：

系统的配置参数：系统在启动过程中通常会首先读启动参数，可以在系统启动后将这些参数输出到日志中，方便确认系统是按照期望的参数启动的；
后台定期执行的任务：如定期更新缓存的任务，可以记录任务开始时间，任务结束时间，更新了多少条缓存配置等等，这样可以掌握定期执行的任务的状态；
异常处理逻辑：如对于分布式存储系统来说，当系统在一个存储节点上读数据失败时，需要去另一个数据节点上进行重试，可以将读数据失败这件事情记录下来，之后可以通过对日志的分析确认是否某些节点的磁盘可能存在故障。再比如，如果系统需要请求一个外部资源，可以将请求这个外部资源偶尔失败又重试成功这件事情记录下来，具体来说：
```
[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
```
因为前者可以让我们预判被依赖的服务器服务质量有风险，也许需要进行扩容；

日志中需要记录关键参数，出错时的关键原因等。例如：

[INFO] RequestID:b1946ac92492d2347c6235b4d2611184, auth failed
[INFO] RequestID:b1946ac92492d2347c6235b4d2611185, content digest does not match
[INFO] RequestID:b1946ac92492d2347c6235b4d2611186, request ip not in whitelist