Python 日志记录指南

对于开发人员来说，最糟糕的事情莫过于试图弄清楚应用程序为什么不能正常工作，而你却不知道它内部发生了什么。有时你甚至无法判断系统是否按设计运行。

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

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

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

本文着眼于 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（日志记录）

日志记录是 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

记录器层次结构

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

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

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

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

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

图片来自

opensource.com

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

回顾工作流程

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

1. 记录器可以被禁用，从而不允许从它们发出任何记录。
2. 可以在记录器和处理器中配置有效级别。

例如，当记录器配置了 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__ 创建一个记录器。它将根据项目结构创建通道和层次结构，因为 Python 模块用点连接。

logger 变量引用记录器 "module"，其父级为 "projectA"，而 "projectA" 的父级为 "root"。

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

在记录消息时，除了模板参数外，我们还可以传递具有特定含义的关键字参数。最有趣的是 exc_info 和 stack_info。这些将分别添加有关当前异常和堆栈帧的信息。为方便起见，记录器对象中提供了一个方法 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'

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

配置我们的记录器

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

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

BasicConfig

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

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

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

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

DictConfig

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

这是一个例子

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

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

扩展 logging

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

Logging JSON（日志记录 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 类 也可能引起您的兴趣。

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

更多信息

本篇对 logging 库的灵活性和可配置性的介绍旨在展示其设计如何巧妙地分离关注点。它还为任何有兴趣更深入了解 logging 文档 和 how-to 指南 的人提供了坚实的基础。尽管本文不是 Python 日志记录的全面指南，但以下是几个常见问题的解答。

我的库发出“no logger configured”警告

查看来自“The Hitchhiker's Guide to Python”的 如何在库中配置日志记录。

如果记录器没有配置级别会发生什么？

记录器的有效级别将由其父级递归定义。

我的所有日志都在本地时间。如何以 UTC 格式记录日志？

格式化器是答案！您需要设置格式化器的 converter 属性以生成 UTC 时间。使用 converter = time.gmtime。