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（过滤器）

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

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

用户可以使用 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 配置了 INFO 级别时，只会传递 INFO 级别及以上的级别。相同的规则适用于处理器。

考虑到所有这些，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'

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

配置我们的 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

由于其设计方式，扩展 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")

这样做有效地为所有通过该记录器的记录添加了一个属性。然后，格式化程序会将其包含在日志行中。

请注意，这会影响您的应用程序中的所有日志记录，包括您可能正在使用的库或其他框架以及您正在为其发出日志的库或其他框架。它可以用于在所有日志行上记录诸如唯一请求 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 层级结构

回顾工作流程

如何使用 logging

贪婪字符串格式化

捕获和格式化异常

配置我们的 logger

BasicConfig

DictConfig

扩展 logging

记录 JSON

添加更多上下文

缓冲日志

更多信息

10 条评论

相关内容