更智能的错误和日志：让数据发挥作用

引言

日志记录。我们现在应该做得更好。

我指的是什么？市面上有许多日志框架和库，大多数开发人员每天都会使用其中的一个或多个。对于 .Net 开发人员，我能想到的一些例子包括：log4net、nLog、elmah 和 Enterprise Library Logging Application Block。它们简单易用，非常适合开发人员调试代码。但仍然不够。

在您的应用程序离开开发环境后，您是否曾经必须处理过日志文件？如果是，您会很快遇到几个痛点：

• 数据量更大
• 您必须访问数据
• 它分布在多个服务器上
• 一个特定的操作可能跨越服务边界——因此需要处理更多的日志
• 它是扁平化的，难以查询——即使您将其放入 SQL，也需要进行大量索引才能使其可用
• 难以阅读
• 您通常没有任何用户等的上下文信息
• 您可能缺少一些有用的详细信息（您是说 "log.Info('在方法中')" 没有用吗？？？)
• 管理日志文件轮换和保留

此外，您生成了所有关于您的应用程序的丰富数据，而您却没有主动利用它们。

是时候认真对待了。

一旦您在开发环境之外处理应用程序，日志消息（包括异常）通常是您快速发现应用程序中某个功能为何不正常工作的唯一途径。当然，APM 工具可以提醒您内存泄漏和性能瓶颈，但通常缺乏足够的详细信息来帮助您解决特定问题，例如（为什么此用户无法登录，或为什么此记录未处理？）。

在 Stackify，我们建立了一种“日志记录文化”，其目标是实现以下目标：

1. 记录一切。尽可能多地记录，以便始终拥有相关的、有上下文的日志，同时又不增加开销。
2. 聪明地工作，而不是拼命工作。将所有日志记录整合和聚合到一个中心位置，供所有开发人员访问，并且易于提炼。此外，寻找新的方法，利用我们的日志记录和异常数据主动改进我们的产品。

在本篇文章中，我们将探讨这些概念，并分享我们为解决这个问题所做的努力，其中许多已经成为 Stackify 的智能错误和日志管理 (SmartELM) 产品的一部分。

记录一切。

我曾在许多地方工作过，那里的日志消息看起来是这样的：

我给开发人员点赞：至少他们使用了 try/catch 并处理了异常。异常可能带有堆栈跟踪，因此我知道它来自哪里，但没有其他上下文。稍后会详细介绍。

有时，他们甚至会进行一些主动的日志记录，如下所示：

但总的来说，这样的陈述并不能让你很好地了解你的应用程序中真正发生了什么。如果你负责排查生产环境中的错误，并且/或者错误只发生在一个（或一部分）应用程序用户身上，那么你就无法获得太多信息，特别是考虑到在用户量很大的应用程序中，你的日志语句可能如同大海捞针。

正如我之前提到的，在无法物理连接和调试的生产环境中，日志记录通常是你拥有的为数不多的生命线之一。你想记录尽可能多的相关、有上下文的数据。以下是我们进行此操作的指导原则：

逐行检查代码。

假设有一个关键进程，您想围绕它添加日志记录（实际上是审计），以便能够查看发生了什么。您可以只在整个进程周围放置一个 try/catch 并处理异常（您应该这样做），但这并不能告诉你关于请求输入了什么。请看以下过度简化的示例。

以以下对象为例，它是一个 Entity Framework Code First POCO 对象。

public class Foo
{
   public int ID { get; set; }
   public int RequiredInt { get; set; }
   public string FooString { get; set; }
}

请注意，它有一个名为 `RequiredInt` 的字段，它是一个 int，出人意料地，不是可空的。

请看以下方法，它创建一个 Foo 并将其保存到数据库。请注意我是如何打开错误之门的——该方法接受一个可空 int 作为输入参数。我将其转换为 int 类型，但没有检查 null。这很容易导致异常。

public static void CreateFoos(int? requiredInt, string fooString)
{
   using (var context = new ApplicationDbContext())
   {
      var foo = new Foo();
      foo.RequiredInt = (int) requiredInt;
      foo.FooString = fooString;
 
      context.Foos.Add(foo);
      context.SaveChanges();
 
   }
}

这是一个过度简化的场景，但它很好地达到了目的。假设这是我应用程序的一个非常关键的部分（不能有任何失败的 Foo！），让我们添加一些日志记录，以便我们知道发生了什么。

try
{
   log.Debug("Creating a foo");
 
   using (var context = new ApplicationDbContext())
   {
      var foo = new Foo();
      foo.RequiredInt = (int) requiredInt;
      foo.FooString = fooString;
 
      context.Foos.Add(foo);
      context.SaveChanges();
 
   }
}
catch (Exception ex)
{
   log.Error(ex);
}

现在，让我们创建一些 foo；一个有效的和一个无效的：

CreateFoos(1,"The foo is 1");
CreateFoos(null, "The foo is null");

现在我们得到了一些日志记录，它看起来像这样：

DEBUG2014-10-31 13:11:08.9834 [11] Creating a foo [CID:(null)]
DEBUG2014-10-31 13:11:10.8458 [11] Creating a foo [CID:(null)]
ERROR2014-10-31 13:11:10.8673 [11] System.InvalidOperationException: Nullable object must have a value.
at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
at System.Nullable`1.get_Value()
at HelloStackify.Web.Controllers.GimmeErrorsController.CreateFoos(Nullable`1 requiredInt, 
    String fooString) in c:\GitHub\StackifySandbox.Net\HelloStackify.Web\HelloStackify.Web\Controllers\GimmeErrorsController.cs:line 57 [CID:(null)]

现在我们有一些日志记录了——我们知道 Foo 何时被创建，何时创建失败。但我仍然感觉缺少一些上下文。上下文：让我们来谈谈这个。在此示例中，使用 log4net，我们有几种选择。

如果您查看 log4net 日志记录方法的签名（log.Debug、log.Info 等），您会发现有几个重载的构造函数。

public static void Debug(this ILog log, string message, object debugData)
{
   log.Debug((object) Extensions.GetMessage(message, debugData));
}

看到那个‘object debugData？’ 看起来像是我们需要的，不是吗？让我们将代码更改为这样：

using (var context = new ApplicationDbContext())
{
   var foo = new Foo();
   foo.RequiredInt = (int) requiredInt;
   foo.FooString = fooString;

   log.Debug("Creating a foo: ",foo);

   context.Foos.Add(foo);
   context.SaveChanges();

}

看看我们文件日志的输出：

DEBUG2014-11-01 09:26:51.8667 [12] Logging a foo [CID:(null)]

嗯。真是的……没有对象。事实证明，您需要一个支持将该对象序列化并输出到日志记录位置（在本例中是文件附加程序）的附加程序。因此，我们需要执行一些额外的步骤。

1. 自己序列化对象（Json.Net 非常适合此目的）
2. 使用 StringBuilder / Formatter 创建日志记录字符串

log.Debug(string.Format("Creating a foo: {0}",JsonConvert.SerializeObject(foo)));

这将产生如下所示的日志输出：

DEBUG2014-11-01 10:39:53.3295 [11] Creating a foo: {"ID":0,"RequiredInt":1,"FooString":"The foo is 1"}

虽然它能达到目的，但存在一些主要的缺点，主要是它都是一个字符串，而且您添加的对象和数据越多，您编写的代码就越多。我不知道您怎么样，但当我编写日志语句时，我希望它快速而简单。Stackify 附加程序支持记录对象，无需先进行序列化。它使得记录复杂的动态对象变得非常容易，例如：

using (var context = new ApplicationDbContext())
{
   var foo = new Foo();
   foo.RequiredInt = (int) requiredInt;

   context.Foos.Add(foo);
   context.SaveChanges();
   log.Debug("Created a Foo", new { Foo=foo,CreatedBy=User.Identity.Name});
}

这可以产生如下出色的输出：

（此输出来自 Stackify 日志记录仪表板，通过 Stackify log4net 附加程序。稍后会详细介绍）。

立即开始免费试用!

诊断上下文日志记录

这让我们想到最后一点：诊断上下文日志记录。您会注意到我记录了创建对象的用户名。当调试生产问题时，您的日志中可能有成千上万条“创建了一个 Foo”的消息，但您不知道是哪个已登录用户创建的。这种上下文信息在快速解决问题时是无价的。想想还有哪些详细信息可能很有用——例如，HttpWebRequest 详细信息。但谁想每次都费心去记录它呢？诊断上下文日志记录来拯救您。例如，Log4net 可以轻松实现这一点。（您可以在此处阅读有关 LogicalThreadContext 的信息：https://logging.apache.ac.cn/log4net/release/sdk/log4net.LogicalThreadContext.html）

启用它非常简单。在您的 log4net 配置中，设置您的逻辑线程上下文变量：

<appender name="StackifyAppender" type="StackifyLib.log4net.StackifyAppender, StackifyLib.log4net">
   <logicalThreadContextKeys>User,Request</logicalThreadContextKeys>
</appender>

然后，只需记录您的上下文项。在我的示例中，我正在记录来自 User（IPrincipal）和 Request（HttpWebRequest）对象的数据。最简单的方法是在每次请求的 Global.asax 中完成。

void MvcApplication_AuthenticateRequest(object sender, EventArgs e)
{
   try
   {
      log4net.LogicalThreadContext.Properties["User"] = User;
   }
   catch (Exception ex)
   {
      log.Error(ex);
   }
}   void MvcApplication_BeginRequest(object sender, EventArgs e)
{

   log4net.LogicalThreadContext.Properties["Request"] = new
   {
      HostAddress = Request.UserHostAddress,
      RawUrl = Request.RawUrl,
      QueryString = Request.QueryString,
      FormValues = Request.Form
   };
}

（注意：因为我不想记录整个Request 对象，所以我只创建了一个具有我关心的属性的动态对象。）

现在，我可以将我的日志记录语句简化为如下内容：

log.Debug("Created a Foo", foo);

并获得如下漂亮的日志语句输出：

这就引出了下一个话题，即努力工作，而不是聪明地工作。但在此之前，我将回答一个我确定会有人在评论中问很多的问题：“但是，如果我记录所有内容，会不会产生开销、不必要的通信和巨大的日志文件？”我的回答分为几部分：第一，使用日志详细程度级别。您可以记录.Debug()所有您认为需要的内容，然后相应地设置生产环境的配置，即只记录警告及以上级别。当您需要调试信息时，只需更改配置文件，无需重新部署代码。第二，如果您以异步、非阻塞方式（例如 Stackify 附加程序）进行日志记录，则开销应该很低。最后，如果您担心空间和日志文件轮换，有更聪明的方法可以做到这一点，我们将在下一节讨论。

聪明地工作，而不是拼命工作。

既然我们正在记录一切，并且它提供了出色的上下文数据，那么我们将着眼于等式中的下一部分。正如我所提到的，并且通过演示，仅仅将所有这些倾倒到平面文件（甚至数据库）中，在大型、复杂的应用程序和部署环境中仍然对您帮助不大。考虑到成千上万的请求、跨越多天、几周或更长时间的文件，以及分布在多个服务器上，您必须考虑如何快速找到所需数据。

我们真正需要的是一个解决方案，该解决方案：

• 将所有日志和异常数据聚合到一个地方
• 立即向您团队中的每个人提供
• 呈现整个堆栈/基础架构的日志时间线
• 高度索引化、可搜索且“智能”

这是我介绍 Stackify SmartELM 的部分。当我们努力提高自己快速高效处理日志数据的能力时，我们决定将其作为我们产品核心的一部分（是的，我们使用 Stackify 来监控 Stackify），并与我们的客户共享，因为我们认为这是应用程序性能和故障排除的关键问题。

首先，我们意识到许多开发人员已经部署了日志记录，并且不想花费大量时间来移除旧代码并替换为新代码。这就是为什么我们为一些最常见的框架创建了日志附加程序（有关所有设置和配置的详细信息，请在此处找到：此处）。

• log4net
• log4j
• nLog
• logback
• Elmah
• 或者使用我们通用的库直接写入我们的 API，该库包含在所有这些附加程序中，或者单独使用。

此外，通过使用这些库之一，您还可以访问 .NET 的自定义指标和 Java 的自定义指标，这些指标与我们的应用程序和服务器监控产品配合得非常好。

以 log4net 为例，设置很简单。只需将二进制文件添加到项目中（您可以将它们放在 \bin 文件夹中，无需重新编译），然后添加一些 web.config 配置：

<log4net>
   <root>
      <level value="ALL" />
      <appender-ref ref="StackifyAppender" />
      <appender-ref ref="LogFileAppender" />
   </root>
<!--Use the following to send only exception and error statements to Stackify -->
   <appender name="StackifyAppender" type="StackifyLib.log4net.StackifyAppender, StackifyLib.log4net">
      <logicalThreadContextKeys>User,Request</logicalThreadContextKeys>
   </appender>
   <appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
      <param name="File" value="stackify.log" />
      <param name="AppendToFile" value="true" />
      <rollingStyle value="Size" />
      <maxSizeRollBackups value="10" />
      <maximumFileSize value="10MB" />
      <staticLogFileName value="true" />
      <layout type="log4net.Layout.PatternLayout">
         <param name="ConversionPattern" value="%-5p%d{yyyy-MM-dd HH:mm:ss.ffff} [%thread] %m [CID:%property{clientid}]%n" />
      </layout>
   </appender>
</log4net>

如您所见，如果您已经在使用附加程序，您可以将其保留在原处并同时使用它们。现在您已经将日志流式传输到 Stackify（顺便说一句，如果安装了我们的监控代理，您还可以将 Windows 事件查看器和 Syslog 文件传输到 Stackify！），我们可以看看日志记录仪表板：

此仪表板显示了来自所有服务器和应用程序的合并日志数据流，并以时间线的形式呈现。从这里，您可以快速：

• 根据时间范围加载日志
• 按特定服务器和应用程序或环境过滤

此外，还有一些非常出色的可用性功能。您首先会注意到顶部的图表。它是快速“分类”您的应用程序的绝佳方式。蓝线表示日志消息的速率，红条表示日志详细信息中的异常数量。在上面的屏幕截图中，两者都看起来相当稳定，但如果我将此图表放大到过去 7 天，它看起来像这样：

显而易见，几天前，我的 Web 应用程序的活动量开始增加（如日志级别所示——Stackify 监控可以通过解析和分析 Web 服务器日志中的流量来证实这些数据），但更重要的是，我们开始收到更多异常。异常的出现会带来 CPU 和内存的开销，而且还会直接影响用户满意度，从而轻松造成实际的金钱损失。

通过放大图表到这个时间段，我可以快速将日志详细信息过滤到该时间范围，并查看该时间范围内的日志。

这里有几点有趣之处：

搜索

看到那个蓝色的文本，看起来像一个 JSON 对象？是的，它是一个 JSON 对象。这是记录对象以及添加上下文属性（也是对象）的结果。它看起来比平面文件中的纯文本更漂亮，不是吗？它甚至更棒。看到页面顶部的搜索框了吗？我可以输入任何我想到的搜索字符串，它会像查询平面文件一样查询我所有的日志。但是，正如我们之前讨论的，这并不理想，因为您可能会获得比您想要的更多的匹配项。假设我想搜索“Hello World”，但只在名为“testString”的属性的上下文中搜索？

幸运的是，我们的日志聚合器足够智能，可以帮助您在这种情况下。这是因为当我们找到日志中的序列化对象时，我们会索引找到的每个字段。这使得执行此类搜索变得容易：

json.testString: "Hello World"

并且只获得我想要的值。但我可以更深入。假设我想只查找该语句，并通过特定用户进行过滤（请记住，我们通过 LogicalThreadContext 将已登录用户添加到每个语句中）：

json.testString: “Hello World” AND json._context._user._Identity.name: jtaylor@stackify.com

这将产生以下结果，其中搜索字符串/对象被特别突出显示。

想知道还可以搜索什么吗？当您将鼠标悬停在日志记录上时，只需点击文档图标 ，您将看到 Stackify 索引的所有字段。（注意：在撰写本文时，我们正在准备发布一个新的搜索 UI，它将提供动态过滤器列表，您可以一键应用，而无需了解任何查询语法。）

异常

您可能还注意到异常消息旁边的小红色错误图标 。这是因为我们对异常的处理方式略有不同。点击它，我们会显示该异常的更深层视图。

我们的库不仅捕获完整的堆栈跟踪，还捕获所有 Web 请求详细信息，包括标头、查询字符串、POST 数据和服务器变量。在此模式中，有一个“日志”选项卡，它提供了来自引发错误的应用程序、发生错误所在的服务器的日志的预过滤视图，时间窗口略早于和晚于异常，以提供更多上下文。想知道此错误发生的频率或多频繁，还是想查看其他发生的详细信息？点击“查看所有发生情况”按钮，瞧！

我可以看到这个错误在过去一天中已经发生了 1462 次，并且速率相当稳定。它告诉我，作为一个开发人员，我有一个相当顽固的 bug。

错误和日志密切相关，在日志记录量很大的应用程序中，有时异常可能会有点被忽略。这就是为什么我们也构建了一个错误仪表板，为您提供相同的聚合视图，但仅限于异常。

在这里，我可以看到几条很棒的数据：

• 在过去几天里，我的异常率急剧上升。
• 我的大部分错误都来自我的“沙盒”环境——每小时大约 120 个。
• 我有几个新错误刚刚开始出现（如红色三角形所示）。

您是否曾经将应用程序的新版本发布到生产环境，并想知道 QA 遗漏了什么？（我不是说 QA 永远不会错过 bug……）错误仪表板来拯救您。您可以实时观察并查看趋势——大量的红色三角形，大量的错误。图表中的巨大峰值？也许您使用量有所增加，因此命中了一个以前已知的错误；或者也许出了有 bug 的代码（例如泄漏的 SQL 连接池）导致 SQL 超时错误比正常情况更多。

事实上，在我写这篇文章时，我发布了一个更改到我正在使用的应用程序，并且忘记了首先发布 EF Code First 迁移（并且没有启用自动迁移）。这种情况正是我所指的。我的仪表板上最显眼的位置是，我看到围绕这个问题的一个新错误，并且它发生了很多。

不难想象各种场景，它可以提供早期预警和检测。嗯。早期预警和检测。这引出了另一个好话题。

显示器

当以下情况发生时，收到警报不是很好吗：

• 特定应用程序或环境的错误率突然增加？
• 一个已解决的错误再次发生？
• 您记录的某个特定操作发生得不够多、太多等等？

Stackify 可以做到所有这些。让我们逐一来看。

错误率

当我们查看错误仪表板时，我注意到我的“沙盒”环境每小时收到大量错误。从错误仪表板，点击“错误率”，然后选择您希望配置警报的应用程序/环境。

我可以配置“每分钟错误数”和“过去 60 分钟总错误数”的监视器，然后选择“通知”选项卡来指定谁应该收到警报以及如何接收。随后，如果使用 Stackify 监控，我还可以在此处配置所有其他警报：应用程序运行状态、内存使用率、性能计数器、自定义指标、ping 检查等。

已解决的错误和新错误

前面，我通过在部署应用程序时未发布我的 Code First 迁移引入了一个新错误。我现在已经修复了它，并通过查看该特定错误的详细信息进行了确认。如您所见，上次发生是在 45 分钟前。

这是一个愚蠢的错误，但很容易犯，因为我没有启用自动迁移。我将把这个标记为“已解决”，这使我可以做一些很酷的事情：如果它再次出现，将收到警报。通知菜单将允许我检查我的配置，默认情况下，我设置为接收所有应用程序和环境的新错误和回归错误通知。

现在，如果将来发生相同的错误，我将收到有关回归的电子邮件，并且它会显示在仪表板上。这是一个很好的自动化功能，可以帮助您在“认为”已解决问题并希望确保其不再出现时提供帮助。

日志监视器

有些事情监控起来并不那么直接。也许您有一个关键进程异步运行，并且它成功（或失败）的唯一记录是日志语句。在本篇博文中，我展示了运行深度查询日志数据的能力，任何这些查询都可以保存并监视。我有一个非常简单的场景：我的查询每分钟执行一次，我们可以监视匹配记录的数量。

如果日志文件是您唯一的指示，这只是检查系统健康状况的一个很好的简单方法。（这里有一个专业技巧：将您的 Windows 事件日志发送到 Stackify 并监视 W3WP 进程崩溃和其他堆栈溢出类型的事件。）

总结

所有这些错误和日志数据都可能非常有价值，特别是当您退一步，从更广阔的视角来看时。下面是此应用程序的应用程序仪表板，其中包含所有监控内容：

如您所见，您可以一目了然地获得一些有价值的上下文数据，错误和日志为其做出了贡献：可用性、满意度和错误。站点正常运行（99.8%），但用户满意度低，错误率高。您可以快速开始深入了解哪些页面性能不佳，以及正在发生哪些错误。

当查看特定错误时，可以看到相关的日志。总而言之，这极大地帮助我们改进了我们自己的产品，以快速检测和解决应用程序问题。

这篇文章涉及的内容很多，感觉我只是触及了表面。如果您深入挖掘，甚至亲自尝试，您就能做到！我已将示例应用程序放在 GitHub 上，您可以登录我们的演示环境并尝试我在此演示的所有功能。

只需访问http://s1.stackify.com。

登录用户：sandboxuser@stackify.com，密码为“sandbox-1”，您将进入一个（有限的）账户，您可以在其中查看和查询所有错误和日志，以及查看应用程序监控。

立即开始免费试用!