改进日志记录以辅助调试

自 2012 年 Folsom 周期开始以来，运营商一直在要求日志消息的记忆性标识符。本提案试图提供这些标识符的功能，而无需更新每个日志消息和通过日志模块传递的字符串。

问题描述

许多商业（闭源）企业应用程序，甚至一些开源项目，都包含每个用户和日志消息的唯一标识符。这些 ID 用作文档和错误报告中的参考点，要么代替日志消息的文本，要么作为补充。消息 ID 还意味着在线搜索在某种程度上可以独立于语言，尽管翻译搜索结果可能仍然需要有人能够阅读英语（如果其主要语言中没有结果）。

作为一个拥有广泛分布式贡献者基础和多服务架构的开源项目，将消息 ID 添加到 OpenStack 提出了一些其他环境无法面临的独特挑战。维护唯一 ID 的中央存储库将非常困难。预料到稍后要编写文档，将 ID 添加到每个日志消息会产生大量价值很小的补丁，从而触发审查、测试作业和其他补丁的重新应用。要求对每个日志调用或仅对某些日志级别使用 ID 将需要对我们的日志库 API 进行不兼容的更改。本提案试图以一种能够让我们交付这些消息 ID 的好处，而无需承担将唯一 ID 引入所有日志调用的费用的方式来解决所有这些问题。

消息 ID 的独特好处已被说明如下

  1. 错误的一个唯一 ID 可以在与其他运营商讨论错误或用户通过支持渠道报告错误时充当记忆性提示。

  2. 消息的唯一 ID 有助于在程序的源代码中找到该消息，通过能够直接跳转到源代码，从而更容易地进行故障排除和调试。

提议的变更

虽然唯一的消息 ID 有用，但维护列表会变得很繁琐。新的规则审查者需要学习才能正确管理分段 ID 值，这会导致沮丧和在审查中的吹毛求疵。首先添加 ID 需要手动工作，并且随着时间的推移保持正确组织会增加我们的维护负担。导致请求消息 ID 的两个主要功能都可以通过最少的源代码更改以其他形式提供，因此本提案描述了以最简单的方式实现目标的途径。

消息位置

通过将相关字段添加到日志格式配置选项，可以在 OpenStack 的任何版本中公开消息的位置（文件名和行号）。根本不需要任何源代码更改。根据所需的详细程度，有 3 种不同的方法可以公开位置。

  1. 当前使用的形式是 %(name)s 字段，它将“logger 名称”引入日志行。OpenStack 中的标准做法是使用 Python 模块名称（通过 __name__ 变量可访问）来获取每个文件的 logger 对象。因此，在大多数情况下，logger 名称和模块名称将匹配。例如，在 nova/api/auth.py 中，该行

       LOG = logging.getLogger(__name__)

causes the logger to be called ``nova.api.auth``.

  2. %(filename)s 字段将完整文件名的最后一部分插入到日志行中。例如，nova/api/auth.py 会生成 auth.py。OpenStack 包含许多具有相同基本文件名的模块，因此这种版本不太可能对调试有用。

  3. %(pathname)s 字段将完整的文件名插入到日志行中。例如 nova/api/auth.py 会生成类似于 /usr/local/lib/python2.7/site-packages/nova/api/auth.py 的内容（实际值取决于软件的打包和安装方式）。这些路径可能非常长，但对于需要该级别详细信息的站点，它是可用的。

文件名只是查找日志消息所需信息的组成部分。另一个是行号。%(lineno)s 字段将插入引入日志行的日志调用的位置的行号。例如，该行

LOG.debug("Neither X_USER_ID nor X_USER found in request")

出现在 nova/api/auth.py 的第 102 行，因此 %(lineno)s 将插入 102 到日志行中。

如上所述， %(name)s 字段已经出现在 oslo.log 设置的默认格式字符串中。%(lineno)s 字段可以很容易地添加到其中。可以将此信息添加到 oslo.log 文档中，以便用户更容易找到。虽然这可能会导致运营商使用非默认配置，但它不太可能破坏现有部署中的日志管道。随着时间的推移，当我们看到行号有多有用时，我们可以重新审视这种方法。

错误标识符

Python 程序中的大多数错误都与从 Exception 类派生的类的实例相关联。这些类具有消息文本，通常具有插入动态值（例如出现问题的特定事物的名称）的能力。Python 的日志库识别异常实例，并且当在存在活动异常的情况下发出日志消息时，可以将异常包含在输出中，从而生成回溯。

通过调用 logger 的 exception() 方法，或将异常信息传递给 error() 或 warning() 等其他方法来记录异常。在所有情况下，日志格式化程序负责获取给定的参数并生成适当的日志输出行。

给定示例日志调用

LOG.exception('the exception log msg')

今天记录异常时，生成的输出如下所示

2017-04-24 15:15:54.823 1108 ERROR oslo.tester:24 [-] the exception log msg
2017-04-24 15:15:54.823 1108 ERROR oslo.tester Traceback (most recent call last):
2017-04-24 15:15:54.823 1108 ERROR oslo.tester   File "./tester.py", line 21, in <module>
2017-04-24 15:15:54.823 1108 ERROR oslo.tester     raise RuntimeError('the error text')
2017-04-24 15:15:54.823 1108 ERROR oslo.tester RuntimeError: the error text
2017-04-24 15:15:54.823 1108 ERROR oslo.tester

请注意，异常名称 (RuntimeError) 和错误文本出现在距离包含传递给 exception() 方法的字符串的第一行错误几行的地方。

oslo.log 中使用的日志格式化程序可以修改为将异常的摘要插入到第一行日志中，以及本地消息。结果如下所示

2017-04-24 15:15:54.823 1108 ERROR oslo.tester:24 [-] the exception log msg: RuntimeError: the error text
2017-04-24 15:15:54.823 1108 ERROR oslo.tester Traceback (most recent call last):
2017-04-24 15:15:54.823 1108 ERROR oslo.tester   File "./tester.py", line 21, in <module>
2017-04-24 15:15:54.823 1108 ERROR oslo.tester     raise RuntimeError('the error text')
2017-04-24 15:15:54.823 1108 ERROR oslo.tester RuntimeError: the error text
2017-04-24 15:15:54.823 1108 ERROR oslo.tester

实际上，无论日志级别如何，我们都可以执行此操作，以便在处理异常的上下文中发出日志消息时，即使日志消息的级别为 INFO 或 DEBUG，该错误也包含在输出中。

有关示例更改，请参阅 https://review.openstack.org/#/c/459424/。oslo.log 提供的其他日志格式化程序也需要更新。

此更改适用于任何 Python 库，而不仅仅是 OpenStack 模块，因此由上游依赖项产生的错误也以相同的方式处理。

我们可以同时允许运营商将错误摘要添加到他们的默认格式中，以便如果他们想将其放置在行中更早的位置，他们可以这样做。如果默认错误摘要值为“-”，则该字段将存在，从而更容易解析日志行。例如，可以将 logging_context_format_string 值设置为

%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s:%(lineno)s [%(request_id)s %(user_identity)s] [%(error_summary)s] %(instance)s%(message)s

以生成以下行（当存在错误时）

2017-04-24 15:15:54.823 1108 INFO oslo.tester:24 [-] [RuntimeError: the error text] a regular log message goes here

或以下行（当没有错误时）

2017-04-24 15:15:54.823 1108 INFO oslo.tester:24 [-] [-] a regular log message goes here

有关此额外灵活性的示例实现，请参阅 https://review.openstack.org/461506。

备选方案

  1. 与此主题相关的第一个公共规范发布在 glance-specs 下，标题为“Glance 错误代码”：https://review.openstack.org/#/c/127482

    Glance 规范最终被移动到跨项目规范存储库，标题为“OpenStack 范围内的日志消息错误代码”：https://review.openstack.org/#/c/172552

  2. 我们可以一劳永逸地声明，这不是我们要添加到 OpenStack 的功能。

  3. 我们可以采用跨项目规范中提出的“情况 ID”提案，如 https://review.openstack.org/460110 中所述，或该文档的替代方案部分中描述的变体之一。

  4. 我们可以将指令添加到默认日志格式字符串中，以自动添加行号。这将可能破坏现有部署中的日志管理管道，因为行格式会更改。

参考资料

实现

负责人

主要负责人

oslo.log 工作：dhellmann

详细记录异常：待定

工作项

  • 添加关于如何在日志消息中包含行号的文档。

  • 使 oslo.log 上下文格式化程序在记录异常时添加异常摘要 (https://review.openstack.org/#/c/459424/)

  • 在适当的情况下，使其他 oslo.log 格式化程序添加异常摘要。（JSON、journald 等）

  • 在适当的情况下，使其他 oslo.log 格式化程序和处理程序包含行号。（JSON、journald 等）

依赖项

无

历史

修订版

发布名称

描述

Pike

引入

注意

本作品采用知识共享署名 3.0 非移植许可协议授权。 http://creativecommons.org/licenses/by/3.0/legalcode