事件日志

日志用来记录系统运行期间发生过的离散事件。相信没有哪一个生产系统能够缺少日志功能，然而也很少人会把日志作为多么关键功能来看待。日志就像阳光与空气，无可或缺却不太被重视。程序员们会说日志简单，其实这是在说“打印日志”这个操作简单，打印日志的目的是为了日后从中得到有价值的信息，而今天只要稍微复杂点的系统，尤其是复杂的分布式系统，就很难只依靠 tail、grep、awk 来从日志中挖掘信息了，往往还要有专门的全局查询和可视化功能。此时，从打印日志到分析查询之间，还隔着收集、缓冲、聚合、加工、索引、存储等若干个步骤，如图 10-3 所示。

图 10-3 日志处理过程

这一整个链条中涉及大量值得注意的细节，复杂性并不亚于任何一项技术或业务功能的实现。接下来将以此为线索，以最成熟的 Elastic Stack 技术栈为例子，介绍该链条每个步骤的目的与方法。

输出

要是说好的日志能像文章一样，能让人读起来身心舒畅，这话肯定有夸大的成分，不过好的日志应该能做到像“流水账”一样，无有遗漏地记录信息，格式统一，内容恰当。其中“恰当”是一个难点，它要求日志不应该过多，也不应该过少。“多与少”一般不针对输出的日志行数，尽管笔者听过最夸张的系统有单节点 INFO 级别下每天的日志都能以 TB 计算（这是代码有问题的），给网络与磁盘 I/O 带来了不小压力，但笔者通常不以数量来衡量日志是否恰当，恰当是指日志中不该出现的内容不要有，该有的不要少，下面笔者先列出一些常见的“不应该有”的例子：

• 避免打印敏感信息。不用专门去提醒，任何程序员肯定都知道不该将密码，银行账号，身份证件这些敏感信息打到日志里，但笔者曾见过不止一个系统的日志中直接能找到这些信息。一旦这些敏感信息随日志流到了后续的索引、存储、归档等步骤后，清理起来将非常麻烦。不过，日志中应当包含必要的非敏感信息，譬如当前用户的 ID（最好是内部 ID，避免登录名或者用户名称），有些系统就直接用MDC（Mapped Diagnostic Context）将用户 ID 自动打印在日志模版（Pattern Layout）上。
• 避免引用慢操作。日志中打印的信息应该是上下文中可以直接取到的，如果当前上下文中根本没有这项数据，需要专门调用远程服务或者从数据库获取，又或者通过大量计算才能取到的话，那应该先考虑这项信息放到日志中是不是必要且恰当的。
• 避免打印追踪诊断信息。日志中不要打印方法输入参数、输出结果、方法执行时长之类的调试信息。这个观点是反直觉的，不少公司甚至会将其作为最佳实践来提倡，但是笔者仍坚持将其归入反模式中。日志的职责是记录事件，追踪诊断应由追踪系统去处理，哪怕贵公司完全没有开发追踪诊断方面功能的打算，笔者也建议使用BTrace或者Arthas这类“On-The-Fly”的工具来解决。之所以将其归为反模式，是因为上面说的敏感信息、慢操作等的主要源头就是这些原本想用于调试的日志。譬如，当前方法入口参数有个 User 对象，如果要输出这个对象的话，常见做法是将它序列化成 JSON 字符串然后打到日志里，这时候 User 里面的 Password 字段、BankCard 字段就很容易被暴露出来；再譬如，当前方法的返回值是个 Map，开发期的调试数据只做了三五个 Entity，觉得遍历一下把具体内容打到日志里面没什么问题，到了生产期，这个 Map 里面有可能存放了成千上万个 Entity，这时候打印日志就相当于引用慢操作。
• 避免误导他人。日志中给日后调试除错的人挖坑是十分恶劣却又常见的行为。相信程序员并不是专门要去误导别人，只是很可能会无意识地这样做了。譬如明明已经在逻辑中妥善处理好了某个异常，偏习惯性地调用 printStackTrace()方法，把堆栈打到日志中，一旦这个方法附近出现问题，由其他人来除错的话，很容易会盯着这段堆栈去找线索而浪费大量时间。
• ……

另一方面，日志中不该缺少的内容也“不应该少”，以下是部分笔者建议应该输出到日志中的内容：

• 处理请求时的 TraceID。服务收到请求时，如果该请求没有附带 TraceID，就应该自动生成唯一的 TraceID 来对请求进行标记，并使用 MDC 自动输出到日志。TraceID 会贯穿整条调用链，目的是通过它把请求在分布式系统各个服务中的执行过程串联起来。TraceID 通常也会随着请求的响应返回到客户端，如果响应内容出现了异常，用户便能通过此 ID 快速找到与问题相关的日志。TraceID 是链路追踪里的概念，类似的还有用于标识进程内调用状况的 SpanID，在 Java 程序中这些都可以用 Spring Cloud Sleuth 来自动生成。尽管 TraceID 在分布式跟踪会发挥最大的作用，但即使对单体系统，将 TraceID 记录到日志并返回给最终用户，对快速定位错误仍然十分有价值。
• 系统运行过程中的关键事件。日志的职责就是记录事件，进行了哪些操作、发生了与预期不符的情况、运行期间出现未能处理的异常或警告、定期自动执行的任务，等等，都应该在日志中完整记录下来。原则上程序中发生的事件只要有价值就应该去记录，但应判断清楚事件的重要程度，选定相匹配的日志的级别。至于如何快速处理大量日志，这是后面步骤要考虑的问题，如果输出日志实在太频繁以至于影响性能，应由运维人员去调整全局或单个类的日志级别来解决。
• 启动时输出配置信息。与避免输出诊断信息不同，对于系统启动时或者检测到配置中心变化时更新的配置，应将非敏感的配置信息输出到日志中，譬如连接的数据库、临时目录的路径等等，初始化配置的逻辑一般只会执行一次，不便于诊断时复现，所以应该输出到日志中。
• ……

收集与缓冲

写日志是在服务节点中进行的，但我们不可能在每个节点都单独建设日志查询功能。这不是资源或工作量的问题，而是分布式系统处理一个请求要跨越多个服务节点，为了能看到跨节点的全部日志，就要有能覆盖整个链路的全局日志系统。这个需求决定了每个节点输出日志到文件后，必须将日志文件统一收集起来集中存储、索引，由此便催生了专门的日志收集器。

最初，ELK 中日志收集与下一节要讲的加工聚合的职责都是由 Logstash 来承担的，Logstash 除了部署在各个节点中作为收集的客户端（Shipper）以外，它还同时设有独立部署的节点，扮演归集转换日志的服务端（Master）角色。Logstash 有良好的插件化设计，收集、转换、输出都支持插件化定制，应对多重角色本身并没有什么困难。但是 Logstash 与它的插件是基于 JRuby 编写的，要跑在单独的 Java 虚拟机进程上，而且 Logstash 的默认的堆大小就到了 1GB。对于归集部分（Master）这种消耗并不是什么问题，但作为每个节点都要部署的日志收集器就显得太过负重了。后来，Elastic.co 公司将所有需要在服务节点中处理的工作整理成以Libbeat为核心的Beats 框架，并使用 Golang 重写了一个功能较少，却更轻量高效的日志收集器，这就是今天流行的Filebeat。

现在的 Beats 已经是一个很大的家族了，除了 Filebeat 外，Elastic.co 还提供有用于收集 Linux 审计数据的Auditbeat、用于无服务计算架构的Functionbeat、用于心跳检测的Heartbeat、用于聚合度量的Metricbeat、用于收集 Linux Systemd Journald 日志的Journalbeat、用于收集 Windows 事件日志的Winlogbeat，用于网络包嗅探的Packetbeat，等等，如果再算上大量由社区维护的Community Beats，那几乎是你能想像到的数据都可以被收集到，以至于 ELK 也可以一定程度上代替度量和追踪系统，实现它们的部分职能，这对于中小型分布式系统来说是便利的，但对于大型系统，笔者建议还是让专业的工具去做专业的事情。

日志收集器不仅要保证能覆盖全部数据来源，还要尽力保证日志数据的连续性，这其实并不容易做到。譬如淘宝这类大型的互联网系统，每天的日志量超过了 10,000TB（10PB）量级，日志收集器的部署实例数能到达百万量级（数据来源），此时归集到系统中的日志要与实际产生的日志保持绝对的一致性是非常困难的，也不应该为此付出过高成本。换而言之，日志不追求绝对的完整精确，只追求在代价可承受的范围内保证尽可能地保证较高的数据质量。一种最常用的缓解压力的做法是将日志接收者从 Logstash 和 Elasticsearch 转移至抗压能力更强的队列缓存，譬如在 Logstash 之前架设一个 Kafka 或者 Redis 作为缓冲层，面对突发流量，Logstash 或 Elasticsearch 处理能力出现瓶颈时自动削峰填谷，甚至当它们短时间停顿，也不会丢失日志数据。

加工与聚合

将日志集中收集之后，存入 Elasticsearch 之前，一般还要对它们进行加工转换和聚合处理。这是因为日志是非结构化数据，一行日志中通常会包含多项信息，如果不做处理，那在 Elasticsearch 就只能以全文检索的原始方式去使用日志，既不利于统计对比，也不利于条件过滤。举个具体例子，下面是一行 Nginx 服务器的 Access Log，代表了一次页面访问操作：

14.123.255.234 - - [19/Feb/2020:00:12:11 +0800] "GET /index.html HTTP/1.1" 200 1314 "https://icyfenix.cn" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.163 Safari/537.36"

在这一行日志里面，包含了表 10-1 所列的 10 项独立数据项：

表 10-1 日志包含的 10 项独立数据项

Logstash 的基本职能是把日志行中的非结构化数据，通过 Grok 表达式语法转换为上面表格那样的结构化数据，进行结构化的同时，还可能会根据需要，调用其他插件来完成时间处理（统一时间格式）、类型转换（如字符串、数值的转换）、查询归类（譬如将 IP 地址根据地理信息库按省市归类）等额外处理工作，然后以 JSON 格式输出到 Elasticsearch 中（这是最普遍的输出形式，Logstash 输出也有很多插件可以具体定制不同的格式）。有了这些经过 Logstash 转换，已经结构化的日志，Elasticsearch 便可针对不同的数据项来建立索引，进行条件查询、统计、聚合等操作的了。

提到聚合，这也是 Logstash 的另一个常见职能。日志中存储的是离散事件，离散的意思是每个事件都是相互独立的，譬如有 10 个用户访问服务，他们操作所产生的事件都在日志中会分别记录。如果想从离散的日志中获得统计信息，譬如想知道这些用户中正常返回（200 OK）的有多少、出现异常的（500 Internal Server Error）的有多少，再生成个可视化统计图表，一种解决方案是通过 Elasticsearch 本身的处理能力做实时的聚合统计，这很便捷，不过要消耗 Elasticsearch 服务器的运算资源。另一种解决方案是在收集日志后自动生成某些常用的、固定的聚合指标，这种聚合就会在 Logstash 中通过聚合插件来完成。这两种聚合方式都有不少实际应用，前者一般用于应对即席查询，后者用于应对固定查询。

存储与查询

经过收集、缓冲、加工、聚合的日志数据，终于可以放入 Elasticsearch 中索引存储了。Elasticsearch 是整个 Elastic Stack 技术栈的核心，其他步骤的工具，如 Filebeat、Logstash、Kibana 都有替代品，有自由选择的余地，唯独 Elasticsearch 在日志分析这方面完全没有什么值得一提的竞争者，几乎就是解决此问题的唯一答案。这样的结果肯定与 Elasticsearch 本身是一款优秀产品有关，然而更关键的是 Elasticsearch 的优势正好与日志分析的需求完美契合：

• 从数据特征的角度看，日志是典型的基于时间的数据流，但它与其他时间数据流，譬如你的新浪微博、微信朋友圈这种社交网络数据又稍有区别：日志虽然增长速度很快，但已写入的数据几乎没有再发生变动的可能。日志的数据特征决定了所有用于日志分析的 Elasticsearch 都会使用时间范围作为索引，根据实际数据量的大小可能是按月、按周或者按日、按时。以按日索引为例，由于你能准确地预知明天、后天的日期，因此全部索引都可以预先创建，这免去了动态创建的寻找节点、创建分片、在集群中广播变动信息等开销。又由于所有新的日志都是“今天”的日志，所以只要建立“logs_current”这样的索引别名来指向当前索引，就能避免代码因日期而变动。

• 从数据价值的角度看，日志基本上只会以最近的数据为检索目标，随着时间推移，早期的数据将逐渐失去价值。这点决定了可以很容易区分出冷数据和热数据，进而对不同数据采用不一样的硬件策略。譬如为热数据配备 SSD 磁盘和更好的处理器，为冷数据配备 HDD 磁盘和较弱的处理器，甚至可以放到更为廉价的对象存储（如阿里云的 OSS，腾讯云的 COS，AWS 的 S3）中归档。
  注意，本节的主题是日志在可观测性方面的作用，另外还有一些基于日志的其他类型应用，譬如从日志记录的事件中去挖掘业务热点，分析用户习惯等等，这属于真正大数据挖掘的范畴，并不在我们讨论“价值”的范围之内，事实上它们更可能采用的技术栈是 HBase 与 Spark 的组合，而不是 Elastic Stack。

• 从数据使用的角度看，分析日志很依赖全文检索和即席查询，对实时性的要求是处于实时与离线两者之间的“近实时”，即不强求日志产生后立刻能查到，但也不能接受日志产生之后按小时甚至按天的频率来更新，这些检索能力和近实时性，也正好都是 Elasticsearch 的强项。

Elasticsearch 只提供了 API 层面的查询能力，它通常搭配同样出自 Elastic.co 公司的 Kibana 一起使用，可以将 Kibana 视为 Elastic Stack 的 GUI 部分。Kibana 尽管只负责图形界面和展示，但它提供的能力远不止让你能在界面上执行 Elasticsearch 的查询那么简单。Kibana 宣传的核心能力是“探索数据并可视化”，即把存储在 Elasticsearch 中的数据被检索、聚合、统计后，定制形成各种图形、表格、指标、统计，以此观察系统的运行状态，找出日志事件中潜藏的规律和隐患。按 Kibana 官方的宣传语来说就是“一张图片胜过千万行日志”。

图 10-4 Kibana 可视化界面（图片来自Kibana 官网）