为什么要进行日志测试和如何进行日志测试

\

关键点

\

• 在分布式的、可扩展的系统（通常包含不稳定的基础设施）中排除故障的效率通常取决于是否有充分的日志记录和搜索设备。 \
• 唯一事件ID、事务追踪技术和结构化的日志输出等技术，让我们得以透彻地了解应用程序的行为，以及应用程序是否在正常运作。 \
• 日志记录不再会“拖慢”系统性能，相反地，它在系统故障恢复中有重要的速度增益，尤其是在使用了日志聚合的情况下。 \
• 我们需要测试核心操作需求，如日志记录。 \
• 我们可以采用类似功能性需求的方式来测试日志，比如用户故事和BDD场景等。

\

现代日志聚合和搜索工具为团队的建立、测试和运行软件系统提供了重要的新功能。通过把日志作为一个核心系统组件，并使用如唯一事件ID、事务追踪技术和结构化的日志输出等技术，我们可以获得对应用程序的行为和正常运作的丰富的见解，尤其是跨组件的视图。这篇文章解释了为什么测试日志是有价值的和如何用现代日志聚合工具做日志测试。这种方法使日志成为了一种渠道，使分布式系统更具可测试性。\

日志在整体上会为各方面提速

\

按一直以来的观点，许多人认为，日志会“拖慢”软件。如果使用的是同步文件I / O、慢速磁盘存储、甚至更慢的网络速度，从这些方面来看这种观点有一定的道理。因此，我们往往对在现场环境中运行的软件中记录下来的日志，抱着审慎的态度。然而，异步文件I/O和SSD存储正在成为常态，1GB、10GB，甚至100Gb以太网也越来越普遍，日志的性能特性现在已经变得不同。\

现在，除了时间关键型的应用程序，如金融交易和其他复杂算法的情况下，在软件系统中我们已经很少单纯地优化软件的运行速度了。特别是在分布式系统、云和物联网（IoT）的背景下，我们需要考虑的是在发生错误后，恢复服务的时间（通常被称为“平均恢复时间”，Mean Time to Recovery，MTTR）。同时，我们也要考虑在上游（测试）环境里，确定问题原因所需要的时间。\

现代日志聚合和搜索工具——比如ElasticSearch、Logstash、Kibana、LogEntries、Loggly、Sematext等等——给我们提供了丰富的方法与我们的软件的进行交互，它提供了丰富的用户接口去判断应用程序的行为，也提供了可编程的REST API来在多台服务器之间搜索和关联事件。\

\

虽然额外的日志记录可能会导致软件程序的执行速度下降5%-10%。但如果在要搜索的位置具有详细的可用信息就可以帮助我们更迅速地诊断问题，加快我们对故障的响应，并且往往可以显著地减少发现一些隐藏得非常深的错误的时间！\

快速的I / O和存储以及现代日志工具的组合——特别是当有工具提供给所有测试人员和开发人员时，就使我们能够把日志作为我们的软件系统的一个重要组成部分；这会让我们产生疑问：如果日志是我们的软件系统的一个重要组成部分，我们该如何测试它呢？\

以包裹追踪做类比

\

我们大多数人都非常熟悉在线包裹追踪工具。这些工具使我们只要有一个追踪ID就能够看到我们的包裹在哪里。这些工具有两个有趣的功能：通过派送网络能够跟踪一个特定的包裹，并且也可以显示出涉及到的这个包裹在不同的时间的各种不同的状态（或事件）。\

\

在跟踪一个包裹时，我们可以看到这些状态，比如“到达仓库”、“运输中”和“已送达”等等；这些都代表了特定的状态或事件，并且每一个都有一个系统内的内部标识符（ID）——事件ID。\

\

在现代的异步分布式软件系统中，我们可以使用一种类似的技术来跟踪跨不同模块的运作执行情况。为了帮助我们做到这一点，我们定义了一些我们自己的事件ID，并把这些事件ID与我们正在使用的系统相关联起来。\

预期事件和相关性ID的测试

\

我们不应该把时间花在测试日志子系统本身之上，比如log4net、log4j，等等；我们应该假设日志的功能（写入磁盘、切转日志文件、刷新缓冲，等等）都已经就绪了。相反，我们应该集中精力确保三个独立但相关的东西：\

1. 我们希望发生的事件要在日志流中正确地出现 \
2. 事务标识符（也就是关联ID）如预期一样通过日志流 \
3. 事件按适当的级别被记录（Info、Error、Debug等）——如果我们正在使用可配置的日志级别

当然，通过检查这些东西，我们已经试用了日志子系统和并且隐含地对它也进行了测试。通过把日志作为一个可测试的系统组件，我们也往往会减少问题的“检测时间”，增加团队参与，加强合作，提高软件可操作性。\

我们需要定义一组事件类型ID，这些事件类型ID对应于我们的软件中有用的和关键的操作或执行点。到底要定义多少这样的ID取决于你的软件，但至少我们有ApplicationStarted和DatabaseConnectionFailed或DocumentStoreUnavailable类似的东西（当要用到这些东西时再去定义相应的额外的ID，不要试图事先定义所有可能的事件）。\

例如，如果我们正在用C#构建电子商务应用程序，我们可能会：

public enum EventID\    {\        // Badly-initialised logging data\        NotSet = 0,\        // An unrecognised event has occurred\        UnexpectedError = 10000,\\        ApplicationStarted = 20000,\        ApplicationShutdownNoticeReceived = 20001,\\        PageGenerationStarted = 30000,\        PageGenerationCompleted = 30001,\\        MessageQueued = 40000,\        MessagePeeked = 40001,\\        BasketItemAdded = 60001,\        BasketItemRemoved = 60002,\\        CreditCardDetailsSubmitted = 70001,\\        // ...\    }\

\

我们使用人类可读的名称再加上一个唯一整数值一起作为事件ID，这样就可以将相关或相类似事件组合在一起：在这里，所有有关“篮子”的事件类型会使用60000到69999之间的整数ID。当我们的软件在代码中处理到相应的状态时，它会将相关的事件类型的ID与其他日志数据一起写入日志文件中。这反过来又被日志聚合系统收集起来，可以提供给搜索（通过浏览器和一个API）使用。\

\

如果我们想把一个关于发生在日志流中预期或意外事件的测试用例自动化，我们可以通过curl做一个简单的API调用来进行查询。\

例如，我们可能想检查发生了一次数据库查询（预期发生事件DatabasePreQuery 和DatabasePostQuery）并且没有出现连接问题（突发事件DatabaseConnectionFailed）。\

这里是为DatabasePreQuery事件（你也可以在GitHub找到它）查询Elasticsearch API （在本地运行）的curl命令：

$ curl -XGET 'http://localhost:9200/_search?q=message:DatabasePreQuery\u0026amp;pretty'\

\

这个查询的结果可能是，例如（为了清晰度重新格式化过，并添加了行数以供参考）：

1  {\2    \"took\" : 19,\3    \"timed_out\" : false,\4    \"_shards\" : {\5      \"total\" : 20,\6      \"successful\" : 20,\7      \"failed\" : 0\8    },\9    \"hits\" : {\10     \"total\" : 1,\11     \"max_score\" : 11.516103,\12     \"hits\" : [ {\13       \"_index\" : \"logstash-2016.05.06\