如何打日志

翻译自:https://medium.com/unomaly/logging-wisdom-how-to-log-5a19145e35ec

日志的智慧:如何打日志

上一篇文章我探讨了为什么日志记录很重要,而这篇文章将更深入地探讨如何记录。过去在 Unomaly 工作的的四年中,我与许多公司合作,看到了许多人们如何给应用程序打日志的例子。在这篇文章中,我想分享这些经验,并给出一些关于如何写更好的日志的建议和实用技巧。

关于这方面已经有很多文章了,所以为了节省网上宝贵的空间,并保持它的新奇和有趣,我将在文章最后的 “进一步阅读” 部分列出其他地方已经被广泛接受的最佳实践。

TL;DR

由于我们生活在一个普遍缺乏耐心和时间的时代,这里有一个概括的版本:

  • 把打 log 想象为程序正在写自己的运行日记:进程启动,主要的分支点,错误,不寻常的事件等等。

  • 结构化你的日志。考虑使用混合的方式:自由文本日志,使用 JSON 和 key-value 对拼接。不要使用新的数据格式。

  • 尽量避免多行日志,因为它们经常在到达日志采集器的途中被分开。

  • 永远不要在日志中包含用户敏感的数据,例如密码或身份证号等。

  • 不要吞下异常。相反,要在日志中打印出来,并且让事件的严重性决定它在日志中被记录的细节粒度。

  • 当在关键路径中打日志时,使用抽样而不是聚合。

  • 使用英文打日志。它是软件的通用语言。

什么时候打日志

可以将日志想象为程序的日记,它既应该被人类所读,也应该被计算机所读。它包含描述正在发生的事情的信息,以及作为键值对的相关上下文。另外,请记住它也是应该被用于数据挖掘目的的。因此,包括相关的标识符,如请求 ID、PID、用户 ID 等等。

但是,当程序已经由它的代码和输入定义时,为什么还要写 “日记” 呢?这是一个很有道理的观点。为什么我们不逐行地进行追踪和存储呢?因为它只会产生太多的不相关的数据。日志允许你对程序的操作进行分块,就像注释可以用来解释整段代码一样。

写日志,以便它们告诉负责操作它的人 “程序的执行流程”(ops人员,或者你,在devops 的情况下)。

添加日志的一些好地方是:

  • 代码的主要分支:例如 web 服务中的 GET 和 POST 请求
  • 当出现错误/异常、或得到预期外的值时
  • 重大的特定于业务的事件,例如:某人登录了,或达到了某个阈值
  • 请求失败时、重试时
  • 耗时的批处理操作的开始和结束时

如何序列化数据

让我们看看下边的例子:

1
INFO pkgs.messaging sendMessage: sent message from jane to joe at time Fri, 20 Apr 2018 09:42: Hey Joe, where you goin’ with that logger of yours?

这是不可原谅的,会把人逼疯!为什么呢?

  • 非标准日期格式
  • 未引用的用户数据使其与日志中的其他元数据不可分离
  • 没有明显的键值句柄可用于解析。你需要自定义正则表达式来从中提取任何结构化数据,这意味着通常它的结构化数据不会被提取(因为没人去做这个)

问题是,当开发人员编写上面的代码时,它可能看起来像这样:

1
logger.Info(“sent message from ${from} to ${to} at time ${t}: ${message}”, context)

看起来不太糟,对吗?

问题是,通过一个格式字符串序列化所有东西,所有的元数据信息(即不同的字段的意思)是丢失的。

另外,即使在相同的代码库中,你也会经常发现日志中记录仪相同数据的许多不同的方法/格式。

日志需要结构化! 结构化日志有点像语义网:这是一个伟大的想法,理论上每个人都喜欢它,但是建立必要的约定的困难 (麻烦) 使人们耸耸肩膀,然后依然坚持他们的旧方法。

那么,该如何编写结构化日志呢?

首先,选择一种格式。由于很少有人喜欢 XML,但是很多人喜欢 JSON,所以我将聊聊如何使用 JSON 进行结构化的日志。但是无论选择何种数据格式,大多数原理都是适用的。

JSON 格式的日志

img

虽然听起来很简单:只是编写 JSON 格式的日志。但仍然会有一个问题:怎么编写?

一种很 naive,但并不罕见的方法是:

1
{“type”: “INFO”, “message”: “INFO pkgs.messaging sendMessage: sent message from jane to joe at time Fri, 20 Apr 2018 09:42: Hey Joe, where you goin’ with that logger of yours?”}

不幸的是,这种写法并没有比之前好到哪里去。现在唯一结构化的数据块是日志级别。编写优秀的 JSON 日志的技巧是 “选择粒度级别”,既要满足开发人员的灵活性,又要满足可解析性的需要。另外一个极端 (细粒度) 是将整个日志设置为格式化的 JSON 结构:

1
2
3
4
5
6
7
8
9
10
11
12
{
“type”: “INFO”,
“module”: “social”,
“method”: “sendMessage”,
“event”: {
“type”: “sent_successfully”,
“from”: “jane”,
“to”: “joe”,
“message”: “Hey Joe, where you goin' with that logger of yours?”,
“time”: 1524817341
}
}

这种写法允许工具自动将日志中的不同信息片段识别为可以进行分析或分类的单个标记。

在最理想的情况下,我认为就应该用以上的方式写日志。但是,一个常见的反对意见是,你的日志变得不可读,因为它在没有工具的情况下看起来是这样的:

1
{“type”:“INFO”,“module”:“social”, “method”:“sendMessage”, “event”:{ “type”:“sent_successfully”, “from”:“jane”, “to”: “joe”, “message”: “Hey Joe, where you goin’ with that logger of yours?”, “time”:1524817341 }}

确实有些难以读懂,我认为这是一些开发人员坚持使用非结构化日志记录的原因。此外,我认为在编写代码时编写一个自由文本日志很容易。试图创造一个一致的和整洁的组织结构很容易将你带入 “自行车棚效应” (琐碎定律) ,以及对 “唯一之路” 的需求。

在这里,我想介绍一种混合方法(即键值对和 JSON 格式混用):

生成自由形式的日志,并将元数据拼接成 JSON 或 key=value 键值对。例如:

1
INFO pkg=social method=sendMessage: successfully sent message {“from”: “jane”, “to”: “joe”, “time”: 1524817341, “message”: “Hey Joe, where you goin’ with that logger of yours?”}

的确,日志级别和消息类型没有被显式声明。但是,与使用非结构化格式编写整个日志相比:the number of choices that go into the above, is much lower。这使得在整个代码库中保持一致的实践更加现实。另外一个优点是,这种方式使得日志相当容易阅读,而无需借助 JSON 格式化管道/工具来阅读。

此外,智能日志分析工具会自动提取它能找到的键值对和 JSON 片段,并将其作为元数据添加到事件中,这样就可以对其进行搜索和索引,这通常足以正确地对所有事件进行分类。

随着事件日志日益成为数据挖掘的主题,我认为将会出现更多既定惯例/最佳实践。然而,到目前为止,我还是支持使用混合方法,因为它的使用门槛很低,它通常只是意味着更坚持一些人们已经知道的实践。

  • 如果在日志中包含复杂的或分层的数据,则将这些部分编写为 JSON
  • 使用简单的 key=value,如果需要,可以使用引号,以获得更简单的数据。关键在于简洁,所以将其包装为JSON 只会使其难以阅读
  • 尽可能少地自己做一些发明。当你觉得需要记录一个管道符分隔的数字列表,使其看起来像一个矩阵时:请停下来,站起来走一走(别再瞎搞了)

多行日志和合理大小的事件

这是一个看法因人而异的问题,但我喜欢将日志消息视为 100 到 1000 个字符长度的简短事件。

不要将程序中发生的一个大过程描述为具有大量数据的单个大事件,而应将其分解为若干个较小的事件,每个事件将更大的过程描述为若干个步骤。

  • 大小以千字节为单位
  • 每个事件都应该有足够的背景来说明其本身的意义。你不需要看周围的事件来理解它的意思
  • 需要有足够的信息来搜索更多的信息(如 requestId、traceId),从而找到其他相关事件

此外,可以将日志消息视为事件。他们应该描述一件事,并且有足够的上下文,从而使得通过它看到正在发生的事情,或者知道该到哪里去寻找更多的信息。如果调试日志所需要的内部数据结构不能满足需要,那么他们将不得不将调试器连接到程序中(debug)。

一些程序将转储大量的内部数据结构作为日志输出。在花了几个小时思考如何编写好的格式的字符串之后,你生成了一个非常重要的内部数据结构的漂亮的单页表表示。开发人员的体验得到了改善,你的团队欢呼雀跃,生活也变得美好了。

然而,在另一个角落,事情就不那么美妙了。一个操作人员试图弄清楚为什么发生了错误,但只有以下记录:

1
oc=0x1A 1ffA 38bd 1f3d 85af 12fa d901 be02 […]

格式化良好的多行数据转储在此过程中被分解。虽然理论上支持多行日志,但在实践中,大多数日志路由设置都会出错。

因此,避免多行日志通常是好的。或者,将日志包装在 JSON 中可以消除多行问题,因为这将确保换行符被转义。但是,保持它尽可能简洁的规则仍然需要坚持——don’t log blob’s of JSON as single events。

通过采样记录关键路径

不记录日志的一个常见原因是请求量大的进程,您不可能对每个请求都进行大量的日志记录。

在这里,许多人只是完全跳过日志记录,而采用报告聚合的方式,例如:periodic check: users_logged_in=10 with mean_session_time=12min。这对于查看整体运行状况是非常有用的,但是对于发现单个请求的瓶颈是毫无意义的。

一个更强大的方法是抽样:在每个请求中添加日志语句,但只输出其中 X% 的样本。每个日志语句可以包装在shouldILog() 类型的语句中,使其不会执行,除非它将为特定的请求采样。

如果有足够的请求,这将足够及时地捕获几乎每一种类型的请求的至少一个实例,包括那些命中尾部延迟的请求。Charity Majors 在演讲中对此做了说明。(我知道我在上一篇文章中也提到了这一点。我觉得她很棒!)

不要吞下异常

“永远不要吞下异常!”

你以前可能也听过有人这么说。如果这一段有什么值得学到的,就是这句话了。

为了说明这意味着什么,请看下面的内容:

1
2
3
INFO: everything is fine
FATAL: universe reached heat death, errno=EINTR
INFO: flushed to database n_objects=10 time=30ms

在这里,日志的读者将非常想知道第二行左右发生了什么。

虽然发生了非常严重的事情,但没有提供更多内容。

这种情况经常发生在 catch 子句中,后面跟着一个日志,有时是 process.exit(),或者更糟的是,仅仅有一个线程崩溃,就把剩下的进程变成了《行尸走肉》中的情节。

无论何时遇到异常,都应该尝试报告与之相关的所有内容。通常,最好的办法就是不要处理它,让它上升到最高点:恐慌、重新抛出或任何适用于你的语言的东西。该语言的默认行为通常非常详细地描述所发生的事情。

但更常见的情况是,有人试图抓住它以重新表达它,然后信息丢失,and turns into shit’s broken, exiting

我想以以下建议来结束这一节:

异常事件应该产生异常后果。如果你的程序达到致命状态,您应该为它提供更多的上下文,而不是提供更多的业务正常类型的事件。

日志级别和敏感数据

对于不同类型的日志,syslog 日志有不同的级别。

这些在标准中有很好的定义,但是在实践中经常会看到它们被滥用。

要遵循的一个好规则是考虑输出的信息类型。大致上,我们可以把它分为两类:

  1. 输入程序处理的数据,可能高度敏感。例如,用户的身份证号码
  2. 程序内部工作的数据,例如当前 LRU 缓存的大小

一个常见的例子是明文密码,好的程序会在输出中屏蔽它们,就像这样:

1
Connecting to database db=foobar username=root password=xxxxxx

但是,请注意,这个例子模糊了两者之间的界限,因为包含了用户名。在这一点上,我们需要练习一些常识。

一条经验法则是:永远不要在日志中包含敏感的用户数据。

另外,确保你没有 在DEBUG 日志级别运行你的生产代码。这似乎是显而易见的,但我见过很多次。可能是因为有人急于调试一个破碎的流程,并对其进行了硬编码。有很多方法可以做到这一点,但是将日志级别作为运行时配置的一部分,这与 dev 和 prod 不同,可以防止这种情况的发生。

“English ****, do you speak it?!”

你永远不知道,在某个遥远的国家,有一天会有谁看到你的日志,并因为你使用了你的母语而咒骂你。

互联网是 (或者至少应该是) 无国界的,让我们尽可能地让它具有包容性。因此,请用英文写日志。

总结

希望这篇文章能让你了解到打日志的行为准则!这只是我分享的经验,所以我也想听听你的,请通过 @unomaly 分享出来:我们希望看到你在日志实践过程中的宝石,以及噩梦。

在下一篇文章中,我们将讨论如何将异常检测应用到日志中。

这个博客不应该是一个营销渠道,而是一个产品不可知的地方,让我们的技术团队表达自己和我们正在做的事情。因此,本着完全公开的精神:这是 Unomaly 的核心业务,但我认为,无论你使用什么产品进行日志分析,这都是相关的:通过只强调与以前不同的东西的视角来看待你的数据。

感谢阅读,敬请关注。

Peace, out.
– Emil

Further reading

发布于

2022-03-13

更新于

2022-03-13

许可协议

评论