警告比错误先到

错误爆发的时间不是事件的开始，而是已经在进行中的热化已经超过临界值的时间，真正的开始是在之前的警告部分。

概念图: “什么时候变得不正常” · 1.确定每个日志知道什么。 · 2.调整时间轴。 · 3.按等级抽取首次登场时间。

调查故障时，大多数人从错误日志开始看。虽然很自然，但错误从故事的中间开始。

典型的热化是这样的进行。如果有任何变化→部分请求开始变慢（警告）→慢请求越来越多，抓住资源→超时（错误）→超过临界值，发出警报。光看错误日志，就会看到最后两个步骤。

所以调查中应该问的问题不是“什么时候开始出现错误”，而是**“什么时候变得不正常”**。警告级别日志的第一出现时间往往是答案。

叠加多个日志形成因果的过程是这样的。

**1.确定每个日志知道什么。**访问日志知道用户经历了什么。应用程序日志知道为什么失败。慢查询日志知道时间花在了哪里。部署历史记录知道发生了什么变化。一个日志不能回答所有问题。

**2.调整时间轴。**这是在实际工作中最常遇到的问题。如果一个服务记录为UTC，另一个服务记录为没有偏移的本地时间，同样的事件就会显示出9小时的差异，没有办法进行排序。因此，在结构化日志中，在时间戳中添加偏移值是规则。处理已经创建的日志时，首先确认每个文件的视觉表示方式后再开始。

3.按等级抽取首次登场时间。 warn 的首次登场时间和 error 的首次登场时间。这两个时间之间的间隔就是“错过的时间”。

4. 对比原因候选和视图。 部署历史、设置更改、流量变化。视图重叠时是强有力的线索，不重叠时该候选被删除。

**5.确认方向。**关系不是因果关系。A比B发生得早是必要条件，不是充分条件。如果发布时间是03:19，错误时间是03:27，顺序是正确的，但需要确认该发布是否真的是原因，要否认后症状消失。

在这里，结构化日志的值被揭示出来。在一条日志中service.version如果有这个，可以只用日志回答“是因为发布吗”的问题。如果没有，就需要找到单独的发布记录，然后调整时间，需要30分钟才能找到知道该记录在哪里的人。

出于同样的理由request_id很重要。如果没有那个，就必须用视觉方式猜测一个请求在哪个服务中是如何处理的，但在每秒钟有数十个请求进入的系统中，这种猜测几乎总是错误的。

最后，一点实际操作感。错误信息中包含答案的情况比想象的要多得多。db query timeout: table=payments如果有一行，已经有层次（数据）、症状（超时）、对象（payments表）都出来了。在计数日志之前，首先要正确阅读一行。

当人们重叠查看日志时，他们只看到记录下来的东西。然而，在调查中成为决定性线索的是，经常是不在应该的位置的项目。

定期作业只有那天没有。如果每小时巡视的部署日志只有事故时间附近为空，这意味着该部署没有巡视或花了很长时间。因为比起计数巡视次数，寻找没有巡视次数更难，所以定期作业必须在成功时也留下一条记录。只有在失败时留下日志的设计，无法区分“什么都没发生”和“死了什么都没做”。

**只有某项服务的日志不在该范围内。**其他服务会继续记录，但如果只有一个安静，那么该服务就停止了或日志传输中断了。哪个是取决于该服务的上游是否继续发送请求。

**虽然有请求，但没有响应记录。**访问日志上留有请求，但应用程序日志上没有处理结果，说明处理过程中进程消失了。这时需要看那个时间点的结束原因。

因此，绘制时间轴时将每个日志的件数以分钟为单位一起绘制很有帮助。如果只绘制错误件数的话，上面的三个都会看不到，但如果一起绘制全部件数的话，“在这个区间只有这个日志断开”就会一目了然。考虑到调查时间的大部分时间都用于确定要看哪里，这张图给出的价值很大。

而且这次观察会作为下一次的建议。**调查中写着“因为没有这个所以无法确认”的项目，就是需要照样在下个季度追加的日志列表。**如果不在报告中留下这句话，下次故障也会同样被阻止。

这个列表通常很短。请求标识符、部署版本、处理时间和失败时的目标名称。把四个放在一行日志里，下次调查时几乎没有什么重叠的地方了。

分别汇总JSON Lines应用程序日志、慢查询日志、部署历史记录，重新评估警告和错误的视觉间隔，并将三个日志指向的一个原因记录在文件中。