在 ENJOY 工作的一年多，目睹并参与了后台日志系统的变迁，这是一个可贵的经历。这个过程伴随我司业务的增长以及架构的变化，是弥足珍贵的经验。所以我将这段经历记录下来。

深渊混沌，无可名状

我刚来 ENJOY 的时候，我们只有A机房，并没有一个日志收集中心。 Apollo 的日志保存在它们自己的服务器上面，都是纯文本，保存若改天后抛弃掉。 Prometheus 更惨，它前面有一个 nginx 做 LB，但是这个 nginx 的 access log 并没有被认真对待过，prometheus 本身的 log，额，既没有分割，也没有集中处理。就堆在那里，没事没人看，有事也看不出来。

现在回想起来，当时的日志系统就好像一个深渊，看一眼都会掉 san 值， 非常克苏鲁。

矇昧始觉，雪夜曙光

随着 eru 平台的上线，我们终于开始有了一套相对完善的日志收集系统。 eru 平台上主要收集了两种日志：容器产生的日志和 elb 的 access log 。当时 elb 日志系统的体系相当简单：

eru1日志收集系统

这个架构相当简单明了。但是存在一个问题：agent 到日志收集服务器之间缺乏一个缓存（实际上 agent 是有一个比较小的缓存的，但一般没有开），而日志收集服务器作为一个单点，是整个系统最薄弱的一环。整个问题一直困扰着 eru1 。

最早的日志收集服务是用 logstash 做的。 logstash 存在两个问题：1. grok 难写（不多说，说起来都是泪，谁写谁知道）；2. 重启慢，而且当时还遇到一天死几次的情况，让人不得安生。 所以我着手的第一个工作是选择 logstash 的替代品。在各种日志收集工具中，最终我们选择了 heka，这很大一部分原因是宜信的 lain 也在用它。 其实也考虑过知乎的 kids，无奈的是，知乎自己弃坑之余，kids 自己的可扩展性并不好（heka 可以写 lua 脚本）。

最后 eru1 的日志收集服务就采用了 heka， 但当时存在两个问题：1. heka 处理时间时候有点问题，它拿到的是零时区的时间戳，这导致了你看到的 2016-11-29.log 的日志，其实是 2016-11-29 08:00:00 ~ 2016-11-30 07:59:59; 2. heka 处理 elb 数据的 docoder 插件经常会死掉，很尴尬的是，只会死这个插件，想监控都很困难。

随着接入日志的增多，我们开始将日志输出到 ES。 所以为了解决上一段提及的问题2， 我写了一个定时程序，定时访问 ES, 拿最新的时间戳，如果这个时间落后实际时间5分钟，那就重启 heka。 这是一个粗糙的方法。

值得注意的是，这个时候，我们依然保持了 agent 和 elb 直接向 日志收集系统发日志的架构。这导致后来的一场灾难。

一元复始，万象初开

eru1 日志解决不了的如果问题给我们带来了若干困扰，痛定思痛之余，我们设计了 eru2 的日志系统。eru2 日志收集系统最初的设计如下图。

eru2日志收集系统(version 1)

Kafka 在其中扮演了非常重要的角色。有了 Kafka 做缓冲，即使日志收集机器有什么三长两短，我们依然可以补回日志。

在十一长假里面，回到家乡，没有女朋友，也没有 PS4 的程序员小马决定重整日志系统的 heka 插件。 在此之前，他曾经打算用 logstash 替代 heka 作为日志收集服务。 但无奈，grok 还是太难写了，而经过 erulb3 开发的小马，已经能够熟练进行 lua 开发了，所以他重新选择了 heka 作为日志收集工具。于此同时，他用一种简单粗暴的方法解决了 heka 时间戳的问题：既然 heka 总是拿到零时区的时间戳，那我代码里面再把8小时加上去，那总归是东8区的时间了吧。

在十一假期结束的时候，小马已经为 eru2 的日志收集系统构建了一组 heka 插件，eru2 的日志收集已经顺利运作起来了，一起看起来都是如此美好。但是没有人想到，命运的阴谋已经在前方等着他们了。

多事之秋，混乱之治

十月份开始，我们的工作重点落在迁移 apollo 一事上。而在十月中旬，一个潇湘夜雨的晚上，apollo 的 mq 开始疯狂吐日志，然后龙老板发现落地的日志有巨大的延时：晚上7点看到落地的日志还是5点多的日志。更要命的是，在 kafka 上面看到对应的 topic 的 LAG 始终在增大， Offset 一直没有移动。

这里其实包含了三个问题：1. heka 消费了 kafka 的信息之后，并不会改变 kafka 的 Offset， 这是 heka kafka 插件的锅； 2. heka 的日志处理能力； 3. apollo 的日志吐疯了。

为了解决问题1，我在那个周末把 C2 的日志收集工具从 hekad 换成了 logstash，但是在龙老板和小羊把 apollo 的日志给控制住之前，换了 logstash 也无能为力。

正所谓“正入万山圈子中，一山放过一山拦”，时间接近双十一，日志系统依然混乱。而 eru1 日志系统的遗留问题，引发了一次药丸的线上错误, 这次事故的原因简单概括来说，就是：容器产生了大量日志，heka 处理不来， agent 往 heka 这一段堵死了，然后容器到 agent 这一段也堵死了，之后容器就被堵死了。[注1]

为了确保双十一，我们再次改造了 eru1 的日志收集系统。 eru1日志收集系统(双十一改版)

这次的改动是让容器先将容器打到本地的 rsyslog ，后者配置缓存队列，确保1. 有足够能力消化容器产生的日志；2. 在日志收集服务器挂掉的情况下，支持住，尽量不丢日志。这个改动是成功的，我们成功度过了双十一。

但是，从整体来看，整个日志系统到了最危险的时候，C1 的情况可以先放在一边，C2 的 agent log 和 elb access log 的处理方式，多种日志收集工具并存(rsyslog, logstash和heka)。可以说是乱象横生。

如切如磋，如琢如磨

为了结束这种混乱的情况，前一周和 Flex，菊总讨论，我们重新设计了 C2 的日志收集系统。

eru2日志收集系统(version 2) 在过去的两周里面，我们将日志收集系统从双十一之后的混乱状态整理到上图中的状态。现在接入了系统的日志有：

  1. nginx access log;
  2. elb access log; [注2]
  3. eru agent log;

这个改造的过程当中，有一点人生经验是值得拿出来说的：

  1. 可以用 ` rsyslogd -N 1` 来检查 rsyslog 配置；
  2. 截止到本文写作的时候，rsyslog 并没有一个足够好的插件实现“日志输出到 hdfs”这个任务，omhdfs 安装就是麻烦事，所以当时就被我们放弃了。omhttpfs 性能跟不上，也不够稳定，试用之后被我们放弃了；
  3. rsyslog 队列模型 。rsyslog 所有输入都会进入 rsyslog main queue。 然后 rsyslog 会将信息分发到对应的 ruleset 的队列。ruleset 所有 action 会并行处理消息，当所有 action 都处理了这个消息之后， 这条消息会在 rsyslog main queue 中出队。换言之：一条消息在 main queue 中停留的时间，会取决于它对应的 ruleset 中最慢的 action。关于 rsyslog 的队列模型，可以参考以下文档：Understanding rsyslog Queues, Turning Lanes and Rsyslog Queues 。[注3]

了解了 rsyslog 队列模型之后，我们对为每个 action 配置了独立的队列，这样 main queue 堵塞从而引发日志延时的可能性大大减低。

其路漫漫，上下求索

目前 C2 机房的日志收集系统已经初步完善，更多的日志可以方便地接入这个系统。更多的问题将会随着业务增长接踵而来。眼下有几个重要的问题：

  1. 如何提供一个方便的日志查阅工具?
  2. 随着日志量的增长，服务收集日志的 rsyslog 中心，该如何扩展？
  3. 收集到的日志，还可以发挥什么作用？

以上就是谦卑的平台工程师小马的记录，他把这些记录予以发表，是为了总结过去“一点微不足道的工作”，使之不因为岁月的流逝而被人们遗忘。[注4]

[注1] 这个错误发生在双十一之前的周五，上午发生了问题之后，我们怀疑是日志的问题，但是还不知道发生问题的具体环节，直到晚上更严重的事故处理完之后，我们才开始更细致的排查，找到原因。造成事故难以排查的原因是 product 对 akihabara 的强依赖，而它们恰好都上了会产生大量日志的版本。我认同CMGS的看法：这个时候就应该严格控制变量。

[注2] nginx 负责将流量分发到 elb， 而 elb 负责将流量分发到容器。在系统迁移的过程当中，经常出现 nginx 没有将流量分发到正确的 elb 的情况（比如将 C2 机房的流量分发到 C1 机房的 elb），如果没有 nginx 的日志，DEBUG 的难度将会上升。

[注3] 这几点经验其实都是 Flex 找到并总结的。

[注4] 这里模仿了两个大人物的名言，其中一个大家都很熟悉，剩下不熟悉的那个是希罗多德。