Python 日志记录指南

图片来源：

Pixabay。CC0

对于开发人员来说，最糟糕的事情莫过于试图找出应用程序无法工作的原因，如果你不知道它内部发生了什么。有时你甚至无法判断系统是否按设计运行。

当应用程序在生产环境中运行时，它们会变成需要跟踪和监控的黑盒子。最简单但最重要的方法之一是日志记录。日志记录使我们能够在开发软件时指示程序在系统运行时发出信息，这些信息对我们和我们的系统管理员都很有用。

正如我们为未来的开发人员编写代码文档一样，我们也应该指导新软件为开发人员和系统管理员生成足够的日志。日志是系统文档中关于应用程序运行时状态的关键部分。当使用日志检测您的软件时，请将其视为为将来维护系统的开发人员和系统管理员编写文档。

一些纯粹主义者认为，有纪律的开发人员使用日志记录和测试几乎不需要交互式调试器。如果我们在开发过程中无法通过详细的日志记录来推理我们的应用程序，那么当我们的代码在生产环境中运行时，就更难做到这一点了。

本文着眼于 Python 的 logging 模块、其设计以及使其适应更复杂用例的方法。这并非旨在作为开发人员的文档，而是作为指南，展示 Python logging 模块的构建方式，并鼓励好奇的人深入研究。

为什么要使用 logging 模块？

开发人员可能会争辩说，为什么简单的 print 语句就足够了？ logging 模块提供了多项优势，包括

多线程支持
通过不同的日志记录级别进行分类
灵活性和可配置性
将如何与什么分离

最后一点，将我们记录的什么与我们如何记录的如何实际分离，实现了软件不同部分之间的协作。例如，它允许框架或库的开发人员添加日志，并让系统管理员或负责运行时配置的人员在稍后决定应该记录什么。

logging 模块中的内容

logging 模块精美地分离了其每个部分的职责（遵循 Apache Log4j API 的方法）。让我们看看日志行如何在模块的代码中传递，并探索其不同的部分。

Logger（日志记录器）

Logger 是开发人员通常与之交互的对象。它们是指示我们要记录什么的主要 API。

给定一个 logger 实例，我们可以分类并请求发出消息，而无需担心它们将如何或在何处发出。

例如，当我们编写 logger.info("Stock was sold at %s", price) 时，我们心中有以下模型

图片来源：

opensource.com

我们请求一行，并且我们假设在 logger 中执行了一些代码，使该行出现在控制台/文件中。但实际上内部发生了什么？

Log records（日志记录）

Log records 是 logging 模块用于传递所有必需信息的包。它们包含有关请求日志的函数、传递的字符串、参数、调用堆栈信息等信息。

这些是正在记录的对象。每次我们调用 logger 时，我们都在创建这些对象的实例。但是，这些对象如何序列化为流呢？通过 handlers（处理程序）！

Handlers（处理程序）

Handlers 将日志记录发出到任何输出。它们采用日志记录并根据其构建目的来处理它们。

例如，FileHandler 将获取日志记录并将其附加到文件中。

标准的 logging 模块已经附带了多个内置处理程序，例如

可以写入文件的多个文件处理程序（TimeRotated、SizeRotated、Watched）
StreamHandler 可以定向到像 stdout 或 stderr 这样的流
SMTPHandler 通过电子邮件发送日志记录
SocketHandler 将 LogRecords 发送到流套接字
SyslogHandler、NTEventHandler、HTTPHandler、MemoryHandler 等

我们现在有一个更接近现实的模型

图片来源：

opensource.com

但是大多数处理程序都使用简单的字符串（SMTPHandler、FileHandler 等），因此您可能想知道这些结构化的 LogRecords 是如何转换为易于序列化的字节的...

Formatters（格式化程序）

让我介绍一下 Formatters。 Formatters 负责将富含元数据的 LogRecord 序列化为字符串。如果没有提供 formatter，则有一个默认的 formatter。

logging 库提供的通用 formatter 类以模板和样式作为输入。然后可以为 LogRecord 对象中的所有属性声明占位符。

例如：'%(asctime)s %(levelname)s %(name)s: %(message)s' 将生成类似于 2017-07-19 15:31:13,942 INFO parent.child: Hello EuroPython 的日志。

请注意，属性 message 是将日志的原始模板与提供的参数进行插值的结果。（例如，对于 logger.info("Hello %s", "Laszlo")，消息将是“Hello Laszlo”）。

所有默认属性都可以在 logging 文档中找到。

好的，现在我们了解了 formatters，我们的模型再次发生了变化

图片来源：

opensource.com

Filters（过滤器）

我们日志记录工具包中的最后一个对象是 filters。

Filters 允许更精细地控制应发出哪些日志。多个 filters 可以附加到 loggers 和 handlers。为了发出日志，所有 filters 都应允许记录通过。

用户可以使用 filter 方法将自己的 filters 声明为对象，该方法将记录作为输入，并返回 True/False 作为输出。

考虑到这一点，这是当前的日志记录工作流程

图片来源：

opensource.com

logger 层次结构

此时，您可能会对模块如此巧妙地为您隐藏的复杂性和配置量印象深刻，但还有更多需要考虑的：logger 层次结构。

我们可以通过 logging.getLogger(<logger_name>) 创建 logger。传递给 getLogger 的字符串可以通过使用点分隔元素来定义层次结构。

例如，logging.getLogger("parent.child") 将创建一个名为“child”的 logger，其父 logger 名为“parent”。 Loggers 是由 logging 模块管理的全局对象，因此可以在我们项目的任何地方方便地检索它们。

Logger 实例也称为通道。层次结构允许开发人员定义通道及其层次结构。

在日志记录传递给 logger 内的所有 handlers 之后，将递归调用父级的 handlers，直到我们到达顶部 logger（定义为空字符串）或 logger 配置了 propagate = False。我们可以在更新后的图表中看到它

图片来源：

opensource.com

请注意，不调用父 logger，只调用其 handlers。这意味着 logger 类中的 filters 和其他代码不会在父级上执行。这是将 filters 添加到 loggers 时常见的陷阱。

回顾工作流程

我们已经检查了职责的划分以及我们如何微调日志过滤。但还有两个我们尚未提及的属性

Loggers 可以被禁用，从而不允许从它们发出任何记录。
可以在 loggers 和 handlers 中配置有效级别。

例如，当 logger 配置了 INFO 级别时，只会传递 INFO 级别及以上的级别。相同的规则适用于 handlers。

考虑到所有这些，logging 文档中的最终流程图如下所示

图片来源：

opensource.com

如何使用 logging

现在我们已经了解了 logging 模块的各个部分和设计，现在是时候检查开发人员如何与其交互了。这是一个代码示例

import logging

def sample_function(secret_parameter):
    logger = logging.getLogger(__name__)  # __name__=projectA.moduleB
    logger.debug("Going to perform magic with '%s'",  secret_parameter)
    ...
    try:
        result = do_magic(secret_parameter)
    except IndexError:
        logger.exception("OMG it happened again, someone please tell Laszlo")
    except:
        logger.info("Unexpected exception", exc_info=True)
        raise
    else:
        logger.info("Magic with '%s' resulted in '%s'", secret_parameter, result, stack_info=True)

这使用模块 __name__ 创建了一个 logger。它将根据项目结构创建通道和层次结构，因为 Python 模块是用点连接的。

logger 变量引用 logger “module”，其父级为“projectA”，而“projectA”的父级为“root”。

在第 5 行，我们看到了如何执行调用以发出日志。我们可以使用方法 debug、info、error 或 critical 来使用适当的级别进行日志记录。

在记录消息时，除了模板参数之外，我们还可以传递具有特定含义的关键字参数。最有趣的是 exc_info 和 stack_info。这些将分别添加有关当前异常和堆栈帧的信息。为了方便起见，logger 对象中提供了一个方法 exception，它与使用 exc_info=True 调用 error 相同。

这些是使用 logger 模块的基础知识。 ʘ‿ʘ。但也值得一提的是一些通常被认为是糟糕实践的用法。

贪婪字符串格式化

应尽可能避免使用 loggger.info("string template {}".format(argument))，而应使用 logger.info("string template %s", argument)。这是一个更好的实践，因为只有在将发出日志时才会使用实际的字符串插值。如果我们在高于 INFO 的级别上进行日志记录，不这样做可能会导致周期浪费，因为插值仍会发生。

捕获和格式化异常

通常，我们希望在 catch 块中记录有关异常的信息，并且可能会直观地使用

try:
    ...
except Exception as error:
    logger.info("Something bad happened: %s", error)

但是该代码可能会为我们提供像 Something bad happened: "secret_key." 这样的日志行。这不是很有用。如果我们像之前说明的那样使用 exc_info，它将产生以下结果

try:
    ...
except Exception:
    logger.info("Something bad happened", exc_info=True)

Something bad happened
Traceback (most recent call last):
  File "sample_project.py", line 10, in code
    inner_code()
  File "sample_project.py", line 6, in inner_code
    x = data["secret_key"]
KeyError: 'secret_key'

这不仅包含异常的确切来源，还包含类型。

配置我们的 loggers

检测我们的软件很容易，我们需要配置日志记录堆栈并指定将如何发出这些记录。

有多种方法可以配置日志记录堆栈。

BasicConfig

这是迄今为止配置日志记录的最简单方法。只需执行 logging.basicConfig(level="INFO") 即可设置一个基本的 StreamHandler，它会将 INFO 级别及以上的所有内容记录到控制台。有一些参数可以自定义此基本配置。其中一些是

格式	描述	示例
filename	指定应创建 FileHandler，使用指定的文件名，而不是 StreamHandler	/var/logs/logs.txt
format	为 handler 使用指定的格式字符串	"'%(asctime)s %(message)s'"
datefmt	使用指定的日期/时间格式	"%H:%M:%S"
level	将根 logger 级别设置为指定的级别	"INFO"

这是一种简单实用的配置小型脚本的方法。

注意，basicConfig 仅在运行时首次调用时有效。如果您已经配置了根 logger，则调用 basicConfig 将不起作用。

DictConfig

所有元素的配置以及如何连接它们可以指定为字典。该字典应具有用于 loggers、handlers、formatters 和一些基本全局参数的不同部分。

这是一个示例

config = {
    'disable_existing_loggers': False,
    'version': 1,
    'formatters': {
        'short': {
            'format': '%(asctime)s %(levelname)s %(name)s: %(message)s'
        },
    },
    'handlers': {
        'console': {
            'level': 'INFO',
            'formatter': 'short',
            'class': 'logging.StreamHandler',
        },
    },
    'loggers': {
        '': {
            'handlers': ['console'],
            'level': 'ERROR',
        },
        'plugins': {
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': False
        }
    },
}
import logging.config
logging.config.dictConfig(config)

调用时，dictConfig 将禁用所有现有的 loggers，除非 disable_existing_loggers 设置为 false。这通常是需要的，因为许多模块声明了一个全局 logger，该 logger 将在导入时实例化，在调用 dictConfig 之前。

您可以在可用于 dictConfig 方法的 schema 中查看。通常，此配置存储在 YAML 文件中并从那里配置。许多开发人员通常更喜欢这种方法，而不是使用 fileConfig，因为它为自定义提供了更好的支持。

扩展 logging

由于其设计方式，扩展 logging 模块很容易。让我们看一些例子

Logging JSON（日志记录 JSON）

如果我们愿意，我们可以通过创建一个自定义 formatter 来记录 JSON，该 formatter 将日志记录转换为 JSON 编码的字符串

import logging
import logging.config
import json
ATTR_TO_JSON = ['created', 'filename', 'funcName', 'levelname', 'lineno', 'module', 'msecs', 'msg', 'name', 'pathname', 'process', 'processName', 'relativeCreated', 'thread', 'threadName']
class JsonFormatter:
    def format(self, record):
        obj = {attr: getattr(record, attr)
                  for attr in ATTR_TO_JSON}
        return json.dumps(obj, indent=4)

handler = logging.StreamHandler()
handler.formatter = JsonFormatter()
logger = logging.getLogger(__name__)
logger.addHandler(handler)
logger.error("Hello")

添加更多上下文

在 formatters 上，我们可以指定任何日志记录属性。

我们可以通过多种方式注入属性。在此示例中，我们滥用 filters 来丰富记录。

import logging
import logging.config
GLOBAL_STUFF = 1

class ContextFilter(logging.Filter):
    def filter(self, record):
        global GLOBAL_STUFF
        GLOBAL_STUFF += 1
        record.global_data = GLOBAL_STUFF
        return True

handler = logging.StreamHandler()
handler.formatter = logging.Formatter("%(global_data)s %(message)s")
handler.addFilter(ContextFilter())
logger = logging.getLogger(__name__)
logger.addHandler(handler)

logger.error("Hi1")
logger.error("Hi2")

这有效地为通过该 logger 的所有记录添加了一个属性。然后 formatter 会将其包含在日志行中。

请注意，这会影响您应用程序中的所有日志记录，包括您可能正在使用的库或其他框架，以及您正在为其发出日志的库或其他框架。它可用于记录诸如所有日志行上的唯一请求 ID 之类的内容，以跟踪请求或添加额外的上下文信息。

从 Python 3.2 开始，您可以使用 setLogRecordFactory 来捕获所有日志记录创建并注入额外信息。 extra 属性和 LoggerAdapter 类也可能引起您的兴趣。

Buffering logs（缓冲日志）

有时，我们希望在发生错误时可以访问调试日志。这可以通过创建一个缓冲处理程序来实现，该处理程序将在发生错误后记录最后的调试消息。请参阅以下代码作为未经整理的示例

import logging
import logging.handlers

class SmartBufferHandler(logging.handlers.MemoryHandler):
    def __init__(self, num_buffered, *args, **kwargs):
        kwargs["capacity"] = num_buffered + 2  # +2 one for current, one for prepop
        super().__init__(*args, **kwargs)

    def emit(self, record):
        if len(self.buffer) == self.capacity - 1:
            self.buffer.pop(0)
        super().emit(record)

handler = SmartBufferHandler(num_buffered=2, target=logging.StreamHandler(), flushLevel=logging.ERROR)
logger = logging.getLogger(__name__)
logger.setLevel("DEBUG")
logger.addHandler(handler)

logger.error("Hello1")
logger.debug("Hello2")  # This line won't be logged
logger.debug("Hello3")
logger.debug("Hello4")
logger.error("Hello5")  # As error will flush the buffered logs, the two last debugs will be logged

10 条评论

本作品根据 Creative Commons Attribution-Share Alike 4.0 International License 获得许可。

为什么要使用 logging 模块？

logging 模块中的内容

Logger（日志记录器）

Log records（日志记录）

Handlers（处理程序）

Formatters（格式化程序）

Filters（过滤器）

logger 层次结构

回顾工作流程

如何使用 logging

贪婪字符串格式化

捕获和格式化异常

配置我们的 loggers

BasicConfig

DictConfig

扩展 logging

Logging JSON（日志记录 JSON）

添加更多上下文

Buffering logs（缓冲日志）

更多信息

10 条评论

相关内容