事件日志

    图 10-3 日志处理过程

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

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

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

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

    • 系统运行过程中的关键事件。日志的职责就是记录事件，进行了哪些操作、发生了与预期不符的情况、运行期间出现未能处理的异常或警告、定期自动执行的任务，等等，都应该在日志中完整记录下来。原则上程序中发生的事件只要有价值就应该去记录，但应判断清楚事件的重要程度，选定相匹配的日志的级别。至于如何快速处理大量日志，这是后面步骤要考虑的问题，如果输出日志实在太频繁以至于影响性能，应由运维人员去调整全局或单个类的日志级别来解决。
    • 启动时输出配置信息。与避免输出诊断信息不同，对于系统启动时或者检测到配置中心变化时更新的配置，应将非敏感的配置信息输出到日志中，譬如连接的数据库、临时目录的路径等等，初始化配置的逻辑一般只会执行一次，不便于诊断时复现，所以应该输出到日志中。
    • ……

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

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

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

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

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

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

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

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

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

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

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