Python 日志记录：深度教程

已发表: 2022-03-11

随着应用程序变得越来越复杂，拥有良好的日志可能非常有用，不仅在调试时，而且还可以为应用程序问题/性能提供洞察力。

Python 标准库带有一个日志模块，它提供了大部分基本的日志功能。 通过正确设置，日志消息可以带来很多有用的信息，包括触发日志的时间和地点以及日志上下文，例如正在运行的进程/线程。

尽管有这些优势，但日志模块经常被忽视，因为它需要一些时间才能正确设置，虽然完整，但在我看来，官方日志文档位于 https://docs.python.org/3/library/logging.html并没有真正给出日志记录的最佳实践或突出一些日志记录的惊喜。

本 Python 日志记录教程并不是关于日志记录模块的完整文档，而是一个“入门”指南，介绍了一些日志记录概念以及一些需要注意的“陷阱”。 这篇文章将以最佳实践结尾，并包含一些指向更高级日志记录主题的指针。

请注意，帖子中的所有代码片段都假设您已经导入了日志记录模块：

 import logging

Python 日志记录的概念

本节概述了日志模块中经常遇到的一些概念。

Python 日志记录级别

日志级别对应于给定日志的“重要性”：“错误”日志应该比“警告”日志更紧急，而“调试”日志应该仅在调试应用程序时有用。

Python中有六个日志级别； 每个级别都与一个指示日志严重性的整数相关联：NOTSET=0、DEBUG=10、INFO=20、WARN=30、ERROR=40 和 CRITICAL=50。

Python Logging 的日志级别

除了 NOTSET，所有级别都相当简单（DEBUG < INFO < WARN），其特殊性将在接下来解决。

Python 日志格式

日志格式化程序基本上通过向其添加上下文信息来丰富日志消息。 了解日志的发送时间、位置（Python 文件、行号、方法等）以及线程和进程等附加上下文（在调试多线程应用程序时非常有用）会很有用。

例如，当通过日志格式化程序发送日志“hello world”时：

 "%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"

它会变成

2018-02-07 19:47:41,864 - abc - WARNING - <module>:1 - hello world

Python 日志消息格式化

Python 日志处理程序

日志处理程序是有效写入/显示日志的组件：将其显示在控制台中（通过 StreamHandler）、文件中（通过 FileHandler），甚至通过 SMTPHandler 向您发送电子邮件等。

每个日志处理程序都有 2 个重要字段：

  • 将上下文信息添加到日志的格式化程序。
  • 过滤掉级别较低的日志的日志级别。 因此，具有 INFO 级别的日志处理程序将不会处理 DEBUG 日志。

Python 日志记录处理程序

标准库提供了一些处理程序，对于常见用例来说应该足够了：https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers。 最常见的是 StreamHandler 和 FileHandler：

 console_handler = logging.StreamHandler() file_handler = logging.FileHandler("filename")

Python 记录器

Logger 可能是代码中直接使用最多的，也是最复杂的。 可以通过以下方式获得新的记录器：

 toto_logger = logging.getLogger("toto")

记录器具有三个主要字段：

  • 传播：决定是否应将日志传播到记录器的父级。 默认情况下，其值为 True。
  • A 级别：与日志处理程序级别一样，记录器级别用于过滤掉“不太重要”的日志。 除了，与日志处理程序不同，级别仅在“子”记录器中检查； 一旦日志传播到其父级，将不会检查级别。 这是一种不直观的行为。
  • 处理程序：日志到达记录器时将发送到的处理程序列表。 这允许灵活的日志处理——例如，您可以有一个记录所有 DEBUG 日志的文件日志处理程序和一个仅用于 CRITICAL 日志的电子邮件日志处理程序。 在这方面，logger-handler 关系类似于发布者-消费者关系：一旦通过 logger 级别检查，日志将被广播到所有处理程序。

Python 日志记录的过程

记录器在名称上是唯一的，这意味着如果创建了名为“toto”的记录器，随后的logging.getLogger("toto")调用将返回相同的对象：

 assert id(logging.getLogger("toto")) == id(logging.getLogger("toto"))

正如您可能已经猜到的那样，记录器具有层次结构。 层次结构的顶部是根记录器，可以通过 logging.root 访问。 当使用类似logging.debug()的方法时，会调用此记录器。 默认情况下，根日志级别为 WARN，因此每个级别较低的日志（例如通过logging.info("info") ）都将被忽略。 根记录器的另一个特殊性是它的默认处理程序将在第一次记录级别高于 WARN 的日志时创建。 通常不建议通过类似logging.debug()的方法直接或间接使用根记录器。

默认情况下，当创建一个新的记录器时，它的父级将被设置为根记录器：

 lab = logging.getLogger("ab") assert lab.parent == logging.root # lab's parent is indeed the root logger

但是，记录器使用“点表示法”，这意味着名称为“ab”的记录器将是记录器“a”的子级。 但是，这仅在记录器“a”已创建时才成立，否则“ab”父级仍然是根。

 la = logging.getLogger("a") assert lab.parent == la # lab's parent is now la instead of root

当记录器根据级别检查决定是否应该通过日志时（例如，如果日志级别低于记录器级别，则日志将被忽略），它使用其“有效级别”而不是实际级别。 如果级别不是 NOTSET，则有效级别与记录器级别相同，即从 DEBUG 到 CRITICAL 的所有值； 但是，如果记录器级别为 NOTSET，则有效级别将是第一个具有非 NOTSET 级别的祖先级别。

默认情况下，新记录器具有 NOTSET 级别，并且由于根记录器具有 WARN 级别，因此记录器的有效级别将为 WARN。 因此，即使一个新的记录器附加了一些处理程序，这些处理程序也不会被调用，除非日志级别超过 WARN：

 toto_logger = logging.getLogger("toto") assert toto_logger.level == logging.NOTSET # new logger has NOTSET level assert toto_logger.getEffectiveLevel() == logging.WARN # and its effective level is the root logger level, ie WARN # attach a console handler to toto_logger console_handler = logging.StreamHandler() toto_logger.addHandler(console_handler) toto_logger.debug("debug") # nothing is displayed as the log level DEBUG is smaller than toto effective level toto_logger.setLevel(logging.DEBUG) toto_logger.debug("debug message") # now you should see "debug message" on screen

默认情况下，日志级别将用于决定日志通过：如果日志级别低于日志级别，则日志将被忽略。

Python 日志记录最佳实践

日志模块确实非常方便，但它包含一些怪癖，即使是最好的 Python 开发人员也会长时间头疼。 以下是我认为使用此模块的最佳实践：

  • 配置根记录器，但永远不要在代码中使用它——例如，永远不要调用像logging.info()这样的函数，它实际上会在后台调用根记录器。 如果您想从您使用的库中捕获错误消息，请确保将根记录器配置为写入文件，例如，使调试更容易。 默认情况下，root logger 只输出到stderr ，因此日志很容易丢失。
  • 要使用日志记录，请确保使用logging.getLogger(logger name)创建一个新的记录器。 我通常使用__name__作为 logger 名称，但任何东西都可以使用，只要它是一致的。 要添加更多处理程序，我通常有一个返回记录器的方法（您可以在 https://gist.github.com/nguyenkims/e92df0f8bd49973f0c94bddf36ed7fd0 上找到要点）。
 import logging import sys from logging.handlers import TimedRotatingFileHandler FORMATTER = logging.Formatter("%(asctime)s — %(name)s — %(levelname)s — %(message)s") LOG_FILE = "my_app.log" def get_console_handler(): console_handler = logging.StreamHandler(sys.stdout) console_handler.setFormatter(FORMATTER) return console_handler def get_file_handler(): file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight') file_handler.setFormatter(FORMATTER) return file_handler def get_logger(logger_name): logger = logging.getLogger(logger_name) logger.setLevel(logging.DEBUG) # better to have too much log than not enough logger.addHandler(get_console_handler()) logger.addHandler(get_file_handler()) # with this pattern, it's rarely necessary to propagate the error up to parent logger.propagate = False return logger

在您可以创建一个新的记录器并使用它之后：

 my_logger = get_logger("my module name") my_logger.debug("a debug message")
  • 使用 RotatingFileHandler 类，例如示例中使用的 TimedRotatingFileHandler 而不是 FileHandler，因为它会在文件达到大小限制或每天执行时自动为您旋转文件。
  • 使用 Sentry、Airbrake、Raygun 等工具自动为您捕获错误日志。 这在 Web 应用程序的上下文中特别有用，其中日志可能非常冗长，错误日志很容易丢失。 使用这些工具的另一个优点是您可以获取有关错误中变量值的详细信息，这样您就可以知道哪个 URL 触发了错误、关注的是哪个用户等。

如果您对更多最佳实践感兴趣，请阅读 Toptaler Martin Chikilian 的 The 10 Most Common Mistakes That Python Developers Make。