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 序列化为字符串。如果没有提供格式化器，则有一个默认格式化器。

logging 库提供的通用格式化器类以模板和样式作为输入。然后可以为 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 文档中找到。

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

图片来源：

opensource.com

Filters（过滤器）

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

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

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

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

图片来源：

opensource.com

logger 层次结构

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

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

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

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

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

图片来源：

opensource.com

请注意，不会调用父 logger，只会调用其处理器。这意味着父 logger 中的过滤器和其他代码不会在父 logger 上执行。这是向 logger 添加过滤器时常见的陷阱。

回顾工作流程

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

可以禁用 Logger，从而不允许从中发出任何记录。
可以在 logger 和处理器中配置有效级别。

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

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

图片来源：

opensource.com

如何使用日志记录

现在我们已经了解了 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'

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

配置我们的 logger

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

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

BasicConfig

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

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

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

请注意，basicConfig 仅在运行时首次调用时有效。如果你已经配置了根 logger，则调用 basicConfig 将无效。

DictConfig

所有元素的配置以及如何连接它们可以指定为字典。此字典应具有用于 logger、处理器、格式化器和一些基本全局参数的不同部分。

这是一个例子

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 将禁用所有现有 logger，除非 disable_existing_loggers 设置为 false。这通常是需要的，因为许多模块声明了一个全局 logger，它将在导入时（在调用 dictConfig 之前）实例化。

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

扩展日志记录

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

日志 JSON

如果需要，我们可以通过创建一个自定义格式化器来记录 JSON，该格式化器将日志记录转换为 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")

添加更多上下文

在格式化器上，我们可以指定任何日志记录属性。

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

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 的所有记录添加了一个属性。然后，格式化器将将其包含在日志行中。

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

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

缓冲日志

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

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 层次结构

回顾工作流程

如何使用日志记录

贪婪的字符串格式化

捕获和格式化异常

配置我们的 logger

BasicConfig

DictConfig

扩展日志记录

日志 JSON

添加更多上下文

缓冲日志

更多信息

10 条评论

相关内容