Python日志记录：深入的教程

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

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。

除了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 - a.b.c - WARNING - <module>:1 - hello world

Python记录处理程序

日志处理程序是有效写入/显示日志的组件：在控制台中显示(通过StreamHandler), 在文件中显示(通过FileHandler), 甚至通过SMTPHandler向你发送电子邮件等。

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

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

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

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

Python记录器

记录器可能是在代码中最常直接使用的记录器, 也是最复杂的记录器。可以通过以下方式获取新的记录器：

toto_logger = logging.getLogger("toto")

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

• 传播：决定是否将日志传播到记录器的父级。默认情况下, 其值为True。
• 级别：与日志处理程序级别一样, 记录器级别用于过滤”不太重要”的日志。除了与日志处理程序不同之外, 该级别仅在”子”记录器中检查；一旦日志传播到其父级, 将不会检查该级别。这是一种非直觉的行为。
• 处理程序：日志到达记录器时将发送到的处理程序列表。这样可以灵活地进行日志处理-例如, 你可以拥有一个记录所有DEBUG日志的文件日志处理程序和一个仅用于CRITICAL日志的电子邮件日志处理程序。在这方面, 记录器与处理者的关系类似于发布者与消费者的关系：一旦日志通过记录器级别检查, 日志就会广播给所有处理者。

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

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

你可能已经猜到, 记录器具有层次结构。根记录器位于层次结构的顶部, 可以通过logging.root访问。当使用logging.debug()之类的方法时, 将调用此记录器。默认情况下, 根日志级别为WARN, 因此每个较低级别的日志(例如, 通过logging.info(” info”))都将被忽略。根记录器的另一个特殊之处在于, 它的默认处理程序将在首次记录级别大于WARN的日志时创建。通常不建议通过logging.debug()之类的方法直接或间接使用root logger。

默认情况下, 创建新记录器时, 其父记录器将设置为根记录器：

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

但是, 记录器使用”点符号”, 这意味着名称为” a.b”的记录器将是记录器” 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, i.e. 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开发人员, 也可能导致长时间的头痛。我认为以下是使用此模块的最佳做法：

• 配置root记录器, 但不要在代码中使用它-例如, 永远不要调用logging.info()之类的函数, 该函数实际上会在后台调用root记录器。如果要从使用的库中捕获错误消息, 请确保将根记录程序配置为写入文件, 例如, 以使调试更加容易。默认情况下, root记录器仅输出到stderr, 因此日志很容易丢失。
• 要使用日志记录, 请确保使用logging.getLogger(logger name)创建一个新的logger。我通常使用__name__作为记录器名称, 但可以使用任何东西, 只要它是一致的即可。要添加更多处理程序, 我通常有一个返回记录器的方法(你可以在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触发了错误, 涉及到哪个用户等。

如果你对更多最佳做法感兴趣, 请阅读srcminier Martin Chikilian研究员撰写的Python开发人员的10个最常见的错误。