日志的艺术

目录

• 引言
• 概述
• 什么是日志记录？
• 结构化的日志记录方法
• 我应该记录什么？
• 上下文的重要性
• 并发环境下的日志记录
• 为什么不记录一切？
• 并非所有异常都是错误
• 使用命名日志记录器进行组织
• 单元测试您的日志记录代码
• 结论

引言

本文是对 SLF（Simple Logging Facade）的补充，SLF 是由 Philipp Sumi 和我最近推出的一个开源日志框架。您可以在他的博客上阅读 Philipp 关于 SLF 的精彩介绍以及日志记录如何融入软件开发生命周期，SLF 可在 CodePlex 上下载。

概述

单元测试、设计文档、日志记录——所有这些都是我们知道自己应该做的次要开发活动！对于其中大多数活动，例如单元测试和设计，您可以在网上和书籍中找到大量关于模式、技术和最佳实践的信息。然而，日志记录似乎没有受到同样的关注；因此，开发人员发现很难知道日志记录的“内容、时间、方式”。它重要吗？我认为任何曾经需要在仅有日志文件的帮助下调试实时应用程序的人都会告诉你，“是的！”没有什么比发现一个充斥着无关紧要细节，或者更糟的是，缺少诊断故障所需的关键信息的日志文件更令人沮丧的了。

不幸的是，尽管日志记录很重要，但当应用程序进入生产环境时，与单元测试一样，开发人员倾向于将其“推迟到明天”。对于单元测试，有一个鼓励测试驱动或先测试后编程的整体运动。然而，对于日志记录，它通常作为事后考虑添加到代码库中，或者根本不添加。

日志记录，如同单元测试一样，应该从项目的开始就加以考虑。它是一个有价值的工具，而不是一项枯燥的任务。本文旨在使重要的日志记录任务更像一门艺术，而不是一种事后补充。

什么是日志记录？

我知道你在想，“这很简单，就是把东西写到文件里，对吧？”这个答案虽然部分正确，但过于简单。如果我们稍微详细地分析一下这个问题，将有助于我们回答更重要的问题，例如“我应该记录什么？”

所有计算机应用程序都有某种形式的用户通信接口；对于桌面应用程序，这由 Windows（或其他）操作系统提供；对于 Web 应用程序，该接口通过浏览器远程呈现。这个用户界面是软件与外部世界通信的主要输出机制。用用例（Use-Case）的说法，这是系统与主要参与者（primary actor）通信的机制。保留应用程序执行的操作和内部状态更改的记录，可能有利于应用程序的维护过程。这些信息通常与主要用户无关；因此，应用程序需要一个次要的通信接口。考虑到这一点……

日志记录是将应用程序操作和状态记录到次要接口的过程。

这个定义促使我们更多地思考如何在应用程序中记录信息。我们正在记录应用程序的操作和状态……应该记录哪些操作和状态？我们将其记录到一个次要接口，可以是文件、Web 服务、电子邮件等……接口的性质并不那么重要，重要的是它是一个次要接口。看到这个接口的用户，查看应用程序日志的支持人员，无法访问应用程序的主要接口。这意味着此日志中详细记录的内容非常重要；它通常是诊断问题的关键信息来源。

应用程序日志的消费者可能出于不同的原因想要观察应用程序的操作和状态。上面描述的例子是为了应用程序维护和错误解决。然而，应用程序日志也可能用于创建与应用程序使用相关的统计信息。例如，日志文件可能被用来确定并发用户数量作为性能度量，或者可能被用来探索市场研究目的的使用模式。

显然，日志记录是一项重要的应用程序功能，值得我们稍加思考！

结构化的日志记录方法

应用程序执行的某些状态更改或操作比其他操作更重要。为了满足这种分类需求，所有好的日志框架都为日志消息提供了一个简单的分类系统；SLF 作为一个外观（facade），也这样做。

典型的分类系统为发送到日志的每个条目关联一个日志级别。这些日志级别通常由三种描述应用程序中发生的事件或问题的类型组成，严重程度逐渐增加：WARN、ERROR、FATAL；一个用于一般信息目的：INFO；一个用于调试目的：DEBUG。

日志框架将以结构化的方式写入日志，从而更容易搜索日志中与特定级别相关的条目。此外，一些框架允许您过滤消息，可能会抑制具有特定级别的消息，或将它们重定向到不同的接口，例如，FATAL 消息可以通过电子邮件发送给支持团队，而 DEBUG 消息可能会被完全抑制。

考虑到日志级别的的重要性，在着手一个项目时，开发团队应该就这些级别如何使用达成一致，以确保开发人员之间的一致性。以下是每个级别使用的建议指南

INFO

顾名思义，这些纯粹是信息性消息；它们不应用于指示应用程序中的故障或错误状态。为了有效地使用此日志级别，请尝试思考在主要接口不可访问时，哪些一般信息有助于诊断应用程序错误。一些可能有用的信息包括：

• 与软件相关的版本信息——通常在应用程序启动时将其输出到日志是个好主意。没有什么比在不确定使用的是什么软件的情况下尝试诊断问题更糟糕的了！
• 使用信息——谁在使用该软件？他们目前正在做什么？
• 此应用程序使用哪些外部服务——数据库、Web 服务等……

WARN

这是第一个指示某种应用程序失败的级别。有三个级别可供您使用，一致的使用指南很重要。WARN 级别的消息应用于指示应用程序遇到了潜在问题，但用户体验未受到任何影响。例如，如果一个外部服务无法使用，但提供了执行相同功能的备用服务，则 WARN 消息是合适的。此外，如果重复尝试访问给定资源，则 WARN 消息也是合适的。

ERROR

这是第二个失败级别，顾名思义，它应该表明发生了更严重的事情。ERROR 消息应用于指示应用程序遇到了严重问题，并且因此影响了用户体验。例如，数据库连接可能失败，导致应用程序的部分功能无法使用。

致命错误

这个第三个失败级别应用于指示致命错误。用户体验不仅受到了影响，而且完全停止了！例如，应用程序运行的核心组件发生了以一种不稳定的状态使其无法运行的故障，唯一的可能措施是完全终止应用程序。

DEBUG

此日志级别用于指示记录的消息将用于调试目的——换句话说，这些消息直接面向开发人员。您如何使用它取决于您正在开发的应用程序。许多问题可以通过调试器解决，使 DEBUG 消息变得多余；然而，在少数情况下，DEBUG 消息非常有用，例如：

• 在调试图形渲染桌面应用程序时，启动调试器的过程可能会干扰渲染过程本身。在这些情况下，DEBUG 消息可以成为一种不太干扰的方式来“观察”渲染过程。
• 某些应用程序类型或开发过程的阶段需要特殊的应用程序执行环境。在这些情况下，使用调试器工具可能不是一个可行的选择。在这些情况下，DEBUG 消息可以成为解决棘手 bug 的有用工具。

以上只是 DEBUG 消息有用的两个示例。如前所述，有用性实际上取决于正在开发的应用程序的性质。

我应该记录什么？

现在我们对日志记录是什么有了定义，并对如何使用每个日志级别有了一些指导。现在，是时候回答那个大问题了：“我应该记录什么？”这个问题并不容易回答，它很大程度上取决于正在开发的应用程序的性质。

如果应用程序日志是支持团队在尝试诊断故障时唯一可用的详细信息来源，那么它可能需要非常详细。然而，如果存在其他工具来监控用户活动，则记录的信息可以更稀疏。无论如何，无论所需的详细程度如何，每条单独日志消息的质量都很重要，而这正是本节将主要关注的内容。

上下文的重要性

应用程序是否成功执行任务，通常高度依赖于用户的输入。因此，这些上下文信息在尝试诊断故障时可能至关重要。不幸的是，这些关键的最后一点信息通常缺失。例如，以自动取款机（ATM）为例，这是软件中一个典型的例子。应用程序日志可能如下所示：

2009-06-05 08:15:23 [INFO] User credentials entered
2009-06-05 08:15:23 [WARN] Incorrect PIN
2009-06-05 08:15:37 [INFO] User credentials entered
2009-06-05 08:15:37 [INFO] User credentials validated
2009-06-05 08:15:46 [INFO] Cash withdrawal requested
2009-06-05 08:15:47 [ERROR] Communication failure
Acme.ATM.Integration.ServerException: Unable to connect to bank server
  at Acme.ATM.Integration.WithdrawalService.Connect(): line 23
  ...

如果我们对 ATM 日志进行日常审计以识别问题，那么上述日志文件摘录告诉了我们什么？有用户在两次尝试后成功登录，请求提取现金，然而，此请求由于通信错误而未能得到服务。记录的堆栈跟踪给出了抛出异常的代码行；然而，同一代码可能在当天成功执行了几千次。基本上，上述内容几乎没有提供信息，它告诉我们发生了问题，但几乎没有提供足够的信息来诊断并 hopefully 修复它。问题可能与特定用户、特定银行服务器或其他问题有关。

上述日志中缺少的主要信息是上下文。如果我们只是添加用户的凭据，这可能会为我们提供大量信息，例如他们的账户详细信息，或者他们拥有账户的银行（会不会是该银行的服务器宕机了？）。几个简单的附加上下文信息会让情况大为不同。

2009-06-05 08:15:23 [INFO] User credentials entered, Acc=123765987
2009-06-05 08:15:23 [WARN] Incorrect PIN
2009-06-05 08:15:37 [INFO] User credentials entered, Acc=123765987
2009-06-05 08:15:37 [INFO] User credentials validated
2009-06-05 08:15:46 [INFO] Cash withdrawal requested, Amount=450.00
2009-06-05 08:15:47 [ERROR] Communication failure, server=acmebank.com:345
Acme.ATM.Integration.ServerException: Unable to connect to bank server
  at Acme.ATM.Integration.WithdrawalService.Connect(): line 23
  ...

这次，我们知道是哪个用户，请求了多少金额，以及服务器的地址。有了这些额外的信息，我们现在就有机会追踪 bug 了。或者，即使我们无法从这条日志消息中找到解决方案——未来发生的故障可能会出现一种模式，从而引导我们找到故障。

添加上下文信息对开发过程的努力几乎没有增加。使用 SLF，添加如 ILogger.Info(string format, params object[] args) 等方法，它遵循 `String.Format()` 的模式，通过替换字符串中的占位符来格式化消息，使得将此信息作为格式化消息的一部分变得更加容易。

总而言之，一条没有上下文信息的日志消息通常与没有日志消息一样没有用！

既然谈到了格式化日志消息，那就值得考虑为您的日志消息应用标准格式。如果您需要分析大型日志文件（其中 `grep` 等工具必不可少），这会非常有价值。例如，包含用户名的一条日志消息可能如下所示：

2009-06-05 08:15:37 [INFO] User credentials entered, User=Bob Smith, Acc=123765987

但是，用引号括起用户和账户变量的值，可以更容易地创建正则表达式或其他形式的模式匹配，以在大型日志文件中定位特定值。

2009-06-05 08:15:37 [INFO] User credentials entered, User={Bob Smith}, Acc={123765987}

并发环境下的日志记录

我们将继续使用我们假设的 ATM 示例来说明下一个观点。上面的例子展示了一个用户与系统的交互。让我们假设我们的 ATM 业务逻辑是集中的，多个 ATM 终端与我们的软件交互（就像客户端-服务器一样，Web 服务器和它的远程客户端）。日志片段可能如下所示：

2009-06-05 08:15:23 [INFO] User credentials entered, Acc={123765987}
2009-06-05 08:15:23 [WARN] Incorrect PIN
2009-06-05 08:15:37 [INFO] User credentials entered, Acc={567993322}
2009-06-05 08:15:23 [INFO] User credentials entered, Acc={123765987}
2009-06-05 08:15:23 [WARN] Incorrect PIN
2009-06-05 08:15:37 [INFO] User credentials validated
2009-06-05 08:15:23 [WARN] Account locked - reset required
2009-06-05 08:15:46 [INFO] Cash withdrawal requested, Amount={450.00}

在上面的例子中，我们现在面临两个 ATM 用户并发操作的情况。我们可以看到有几次登录尝试失败，其中一个用户的账户被锁定，而另一个用户成功提取了现金，但哪个客户是哪个呢？

这里的问题再次是缺乏上下文；然而，并发的额外复杂性加剧了这个问题。我们有几个可行的选项：要么每条日志消息都必须足够详细，包含将消息与其他日志消息关联所需的所有上下文信息，要么我们需要通过其他参数（如会话 ID）来关联日志消息。

这是与上面相同的示例，在用户输入凭据时创建了一个顺序的会话 ID：

2009-06-05 08:15:23 [INFO] User credentials entered, Acc={123765987}, Session={5789}
2009-06-05 08:15:23 [WARN] Incorrect PIN, Session={5789}
2009-06-05 08:15:37 [INFO] User credentials entered, Acc={567993322}, Session={5790}
2009-06-05 08:15:23 [INFO] User credentials entered, Acc={123765987}, Session={5791}
2009-06-05 08:15:23 [WARN] Incorrect PIN, Session={5790}
2009-06-05 08:15:37 [INFO] User credentials validated, Session={791}
2009-06-05 08:15:23 [WARN] Account locked - reset required, Session={5790}
2009-06-05 08:15:46 [INFO] Cash withdrawal requested, Amount={450.00}, Session={5791}

在上面的示例中，现在很容易看出哪条日志消息与哪个账户相关。顺便说一句，一些日志框架可以配置为添加上下文信息，例如线程或用户身份（请参阅 log4net 模式布局中的 `%thread` 或 `%identity` 令牌）。然而，在服务器环境中，用户请求每次可能由不同的线程处理，因此需要某种形式的会话信息。

为什么不记录一切？

我们掌握的信息越多，诊断故障就越容易，所以“为什么不记录一切？”这个问题听起来确实很合理。有趣的是，一位不幸的 Stack Overflow 用户描述了他的日志记录方法，就是记录一切：每个方法的开始和结束，方法内代码块的开始/结束，方法参数等等……他的回答是当时一个备受争议的 codinghorror 博客文章的主题。

过度日志记录存在许多问题：

• 日志代码行与其他代码行一样，需要时间和维护。过度日志记录成本高昂。
• 如果应用程序每秒写入日志几千行，性能将受到影响。
• 冗长而详细的日志文件充满了无关信息，分析起来需要很长时间，从而掩盖了真正重要的信息（我敢打赌有一个与日志记录相关的双关语，意思是“看不清树林”，答案请寄明信片……）。
• 如果出于某种原因，您确实需要这种级别的详细信息，那么有更好的方法来添加它，而不是手动输入！AOP 框架（如 PostSharp）可以通过一些简单的配置更改，为您的编译代码添加高度详细的日志记录。

事实很简单，关于每个被调用的方法的详细日志消息几乎总是没有必要的。有了正确的上下文信息，很容易就可以追溯程序的执行——幸运的是，计算机程序是确定性的！

并非所有异常都是错误

一个常见观察到的模式是：

try
{
  ComponentX.DoStuff();
}
catch (Exception e)
{
  log.Error("ComponentX threw an exception", e);
}

每次捕获到异常时，都会向日志发送一个 ERROR 级别的消息。问题在于，异常常常是预期到的，甚至是期望到的。根据上述定义，ERROR 级别的消息是针对那些用户体验受到影响或降级的消息。捕获异常时，在将其记录为 ERROR 之前请三思……

使用命名日志记录器进行组织

大型应用程序通常由众多复杂组件构成。如前一节所述，好的消息是简洁的，并提供最重要的上下文信息。由于组件经常执行类似的任务，如身份验证或连接数据库，因此有时很难确定是哪个组件向日志写入了特定消息。这时，命名日志记录器的概念就变得非常有用了。日志记录器在给定名称后，每次用于提交消息时都会将自己的名称写入日志。但是，应该使用什么名称呢？

我们的应用程序代码已经有一个用于组织它的命名系统，即类名和命名空间。一种常见的日志记录范例利用了这种现有的组织方式，通过其名称将一个日志记录器与每个记录信息的类关联起来。

namespace Acme.Components.Things
{
  class WidgetClass 
  { 
    static Logger logger = LoggerService.GetLogger("Acme.Components.Things.WidgetClass"); 

    // other class members go here  
  }
}

或者，您也可以通过使用类的 `FullName` 来消除对字符串字面量的需求。

namespace Acme.Components.Things
{  
  class WidgetClass 
  { 
    static Logger logger = LoggerService.GetLogger(typeof(WidgetClass).FullName); 

    // other class members go here  
  }
}

从此类的日志记录器实例记录的任何消息都将带有名称 `Acme.Components.Things.WidgetClass`，从而可以明确地将其与该类相关联。

单元测试您的日志记录代码

我知道你在想，“这会不会有点太过了？”任何单元测试其日志记录代码的人要么是单元测试狂热者，要么是覆盖率指标的奴隶。希望本节能说服您，单元测试您的日志记录代码是有价值的。

一个好的开发人员在进行单元测试时是务实的。虽然测试一切有助于确保功能正常，但编写和维护单元测试需要时间，并且会产生相关的成本。因此，在决定是否测试代码中的某个方法或分支时，您应该权衡该代码出现故障的可能性有多大以及出现故障的潜在成本。只有当您觉得编写测试的成本是值得的时，才应该编写它！

在本篇文章的前几节中，我们已经详细说明了日志记录在您的应用程序中扮演着重要角色。如果我们在编写代码时确定某个特定故障（即异常）会影响用户体验，那么记录下来当然很重要。

请记住，用户是奇怪的，您不能总是指望他们主动沟通错误的细节，或者他们是否遇到了错误。有些用户倾向于认为他们在使用中的软件的任何故障都是他们自己的问题，并且会继续使用那些明显不起作用的应用程序。这再次强调了记录重要事件的必要性，以及测试这种记录的必要性。

那么，为什么很少看到日志代码被测试呢？在我整个软件生涯中，我从未见过有人这样做……一次都没有！

这可能是因为代码与配置为将日志消息写入文件的日志框架紧密耦合。为单元测试配置所选的日志框架、读取消息以及事后清理不是一件容易的事。然而，有了 SLF，这不再是问题；在单元测试时，我们可以简单地插入一个将记录的消息保存在内存中的日志记录器，以便在验证测试时重放。这里有一个简单的例子：

public class CommunicationLogic
{
  /// <summary>
  /// The <see cref="ILogger"> used to log messages
  /// </see>
  /// </summary>
  private static ILogger logger = 
     LoggerService.GetLogger(typeof(CommunicationLogic).FullName);

  /// <summary>
  /// A service used by this class
  /// </summary>
  private IRemoteService remoteService;

  public CommunicationLogic(IRemoteService remoteService)
  {
    this.remoteService = remoteService;
  }

  public void SendMessage(string message)
  {
    try
    {
      remoteService.SendMessage(message);
    }
    catch (Exception e)
    {
      logger.WarnFormat(e, "Failed to send the given message [{0}]",
        message);        
    }
  }
}

上面的类依赖于另一个组件 `IRemoteService`，并且有一个名为 `SendMessage` 的方法，我们希望对其进行测试。该方法的实现很简单；它只是委托给 `IRemoteService` 来发送消息。一个积极的测试，其中我们创建一个依赖服务的存根，可能如下所示：

[TestMethod]
public void SendMessage_RemoteServiceOK_MessageSent()
{
  // create our test fixture
  StubbedRemoteService service = new StubbedRemoteService();
  CommunicationLogic comLogic = new CommunicationLogic(service);      

  // run the test
  string message = "Hello World!";
  comLogic.SendMessage(message);

  // verify that the given serivce was used to send the message
  Assert.AreEqual(message, service.SentMessage);
}

/// summary
/// A stub IRemoteService for test purposes
/// summary
private class StubbedRemoteService : IRemoteService
{
  public string SentMessage = null;

  public void SendMessage(string message)
  {
    SentMessage = message;
  }
}

在这里，我们提供了一个“存根”实现的服务，它只是记录正在发送的消息。因此，这是一个真正的单元测试。

现在，我们希望验证，如果远程服务抛出异常，导致我们的消息未被发送，那么此失败是否被记录下来。为了做到这一点，我们首先扩展我们的存根实现以强制失败：

private class StubbedRemoteService : IRemoteService
{
  public bool FailOnSend = false;

  public string SentMessage = null;

  public void SendMessage(string message)
  {
    SentMessage = message;
    if (FailOnSend)
    {
      throw new Exception("Message send failed");
    }        
  }
}

然后，我们将 SLF 配置为向我们要测试的类提供一个 `TestLogger`。现在我们可以验证失败已被记录下来：

[TestMethod]
public void SendMessage_RemoteServiceFails_FailureLogged()
{
  // ensure that we record logged messages by supplying a test logger
  // because our class under creates a static logger, we have to 'inject' our
  // test logger.
  TestLogger logger = new TestLogger();
  typeof(CommunicationLogic).GetField("logger", 
      BindingFlags.NonPublic | BindingFlags.Static).SetValue(null, logger);

  // create our test fixture
  StubbedRemoteService service = new StubbedRemoteService()
  {
    FailOnSend = true
  };
  CommunicationLogic comLogic = new CommunicationLogic(service);

  // run the test
  string message = "Hello World!";
  comLogic.SendMessage(message);

  // verify that the given serivce was used to send the message
  Assert.AreEqual(message, service.SentMessage);

  // verify that the exception was logged
  Assert.AreEqual(1, logger.LoggedItems.Count);
  Assert.AreEqual(LogLevel.Warn, logger.LoggedItems[0].LogLevel);
  Assert.IsNotNull(logger.LoggedItems[0].Exception);
}

很简单！请注意，虽然我们可以单元测试记录的消息，但这会将单元测试与实现紧密耦合。真正重要的是消息以给定的级别被记录下来，并且异常被包含在内。

结论

与 Philipp 合作创建 SLF 让我对日志记录进行了比以往更深入的思考。我曾参与过各种具有完全不同日志记录风格的项目（从类到类，而不仅仅是项目到项目）；然而，直到现在我才开始思考“日志记录的艺术”本身，并且我终于决定了我认为日志应该如何被记录。

如果您同意我的指南，那太好了！我希望您的日志记录和应用程序的可维护性因此得到改善。如果您不同意，但本文让您对日志记录的思考比以前更多，那么这（几乎）同样好。

如果您认为我遗漏了任何内容，或者不同意我的指南，请随时发表评论，并请访问 SLF 在 CodePlex 上的主页，亲自尝试一下。