Python logging 较佳实践

未经允许，禁止转载。

本文只是列出来我自己在实践中总结出来的几点，并不一定最佳。当然，我也不认为有统一的最佳。

记录日志是程序中尤其是 web 服务中的重要一环，恰到好处的日志记录可以帮助我们了解程序运行情况以及

方便排（shuai）错（guo）。

logger 和 handler

如果使用 logging 不多，可能对 logger 和 handler 这两个概念不熟，大多数还是直接使用 logging.info() 来记录日志。

Python 官方给了一个流程图来说明日志消息（LogRecord）在 logger 和 handler 之间的流动情况：

总体来说，我们创建一个 logger，通过 logger.info() 来通知 handler，让 handler（如在终端输出日志的 StreamHandler，完整 handler 见 Useful Handlers）来执行真正的记录操作。

打个比方，logger 好比领导，handler 好比员工。默认情况下你都用 logging.info() 来记录日志，相当于 CEO 直接命令所有员工做事。而有了 logger，通常我们会配置模块级的 logger（下文会细说），再使用 logger.info() 来记录日志，这就相当于公司拆分成若干个部门，每个部门领导（模块级 logger）只管自己部门内的员工做事。这样每个事情谁做的更为明确，也可分别对不同部门进行不同的管理（配置）。

格式化日志

logging 的默认日志格式是这样的：%(levelname)s:%(name)s。完整的属性列表见 LogRecord attributes。

例如：

>>> logging.warning("这是一条 WARNING 消息。")
WARNING:root:这是一条 WARNING 消息。

然而这样的格式是完全不够的。除此之外你可能还想知道时间，那么你可以加上 %(asctime)s，时间格式默认为 %Y-%m-%d %H:%M:%S,uuu，通常这已经能够满足要求，如果不能，那你可以通过自定义 datefmt 来定义自己的 logging.Formatter。

例如：

>>> logging.basicConfig(format="%(asctime)s - %(levelname)s: %(message)s")
>>> logging.warning("这是一条 WARNING 消息。")
2019-12-17 14:22:07,639 - WARNING: 这是一条 WARNING 消息。

>>> logging.basicConfig(format="%(asctime)s - %(levelname)s: %(message)s", datefmt="%Y-%m-%d %H:%M:%S")  # 和默认的区别在于不会输出毫秒
>>> logging.warning("这是一条 WARNING 消息。")
2019-12-17 14:24:37 - WARNING: 这是一条 WARNING 消息。

如果要将全部的属性全部记录，那么就是如下的样子：

# logging_test.py
import logging

logging.basicConfig(
    format="%(asctime)s - %(created)f - %(filename)s - %(funcName)s - %(levelname)s - %(levelno)s - %(lineno)d - %(module)s - %(msecs)d - %(name)s - %(pathname)s - %(process)d - %(processName)s - %(relativeCreated)d - %(thread)d - %(threadName)s: %(message)s", 
    datefmt="%Y-%m-%d %H:%M:%S"
)

def main():
    logging.warning("这是一条 WARNING 消息。")

if __name__ == "__main__":
    main()

运行 logging_test.py 就会看到：

2019-12-17 14:40:21 - 1576564821.762118 - test_logging.py - main - WARNING - 30 - 9 - test_logging - 762 - root - /data/liyajun/projects/jindu_v3_dev/test_logging.py - 36431 - MainProcess - 0 - 139905813096192 - MainThread: 这是一条 WARNING 消息。

设置恰当的日志等级

logging 共有 5 种日志等级，每种等级都有等级名称和对应的数值，严重性由高到低分别为：

严格上来说，还有第六种等级：NOTSET，数值为 0，即所有消息都会输出。但这并不是一种有效等级。

这些等级决定了会输出哪些日志，例如如果你设置了等级为 INFO，那么比 INFO 更「安全的」DEBUG 日志便不会输出。这通常表示了你希望该日志有多详细。

有两个地方需要设置等级：logger 和 handler。logger 和 handler 的默认等级都是 NOTSET，但是需要注意的是，如果发现当前 logger 的等级是 NOTSET，那么会自动往上寻找其父级 logger 的等级，直到寻找到一个等级不是 NOTSET 的 logger。

更刺激的来了，root logger 的默认等级是 WARNING。?

也就是说，默认情况下，只有 WARNING 等级往上的消息才会输出：

import logging

logging.debug("这是一条 DEBUG 消息。")
logging.info("这是一条 INFO 消息。")
logging.warning("这是一条 WARNING 消息。")
logging.error("这是一条 ERROR 消息。")
logging.critical("这是一条 CRITICAL 消息。")

#################### 输出 ####################
# WARNING:root:这是一条 WARNING 消息。
# ERROR:root:这是一条 ERROR 消息。
# CRITICAL:root:这是一条 CRITICAL 消息。

如果你只想显示 INFO 以上的消息，那么只需使用 basicConfig 设置即可：

import logging
logging.basicConfig(level=logging.INFO)

logging.debug("这是一条 DEBUG 消息。")
logging.info("这是一条 INFO 消息。")
logging.warning("这是一条 WARNING 消息。")
logging.error("这是一条 ERROR 消息。")
logging.critical("这是一条 CRITICAL 消息。")

#################### 输出 ####################
# INFO:root:这是一条 INFO 消息。
# WARNING:root:这是一条 WARNING 消息。
# ERROR:root:这是一条 ERROR 消息。
# CRITICAL:root:这是一条 CRITICAL 消息。

使用恰当的日志等级

不要一味使用 logger.info() 来记录所有日志。

• 只是便于 debug 的详细日志使用 debug()，如某变量的值
• 常规通知性信息使用 info()，如某接口有新请求
• 有可能非正常的程序行为（如不推荐的输入）但是又不至于程序崩溃报错，使用 warning()，如某变量的值可能不正确时，以便后期排查
• 有非正常的程序行为而且会导致操作不能正确执行或不能正确返回结果时，使用 error() 或者 exception()，如除零错误
• 非常严重的错误，严重到服务或应用崩溃，如未能捕获的异常，通常此时服务已经崩溃了。这个用的比较少

记录 traceback

什么是 traceback？

如果你还不知道，它就是程序出错时你看到的报错信息，类似下面这种你估计很熟悉了：

Traceback (most recent call last):
  File "<string>", line 1, in <module>
ModuleNotFoundError: No module named 'tensorflow'

根据文档：

Traceback objects represent a stack trace of an exception. A traceback object is implicitly created when an exception occurs, and may also be explicitly created by calling types.TracebackType.

即表示了异常的堆栈追踪信息。这在程序出错时是非常重要的，不然你都不知道哪里出错了。同样在日志中也是必须要记录的。

通常我们会使用 try/except 来捕获异常，并在 except 中记录一下，但如果我们只是使用 logging.error(msg) 来记录，那么 traceback 是不会输出的，这样一来就很不方便排错了。

解决方法是我们可以加上 exc_info=True 来输出异常：

logging.error(msg, exc_info=True)

此外，还有个更为方便的函数：loging.exception(msg)，会默认输出 traceback。

如有必要，把日志输出到文件

如果没有进行任何配置，或者使用 basicConfig 进行配置，那么就只有一个 StreamHandler，即日志消息默认输出到终端。

日志的意义就在于查询和排错，那么只输出到终端很明显不满足这个需求，我们需要将其持久化保存，保存到文件中。

我们可以使用 FileHandler、RotatingFileHandler 或 TimedRotatingFileHandler 来将日志输出到文件。

其实除此此之外，还有其他 handler，例如常见的 StreamHandler、NullHandler 和 WatchedFileHandler 等。才疏学浅，在此就不再误人子弟了。

这三个的一个重要区别是：FileHandler 是将日志全部输出到一个文件中，这会造成日志文件越来越大的问题。而后两个是将日志按照某种规则输出到多个文件中，可以缓解单个日志文件过大的问题。

以 TimedRotatingFileHandler 为例，该 handler 可以在指定时间点创建新日志文件。有如下参数可供配置：

• filename：日志文件名
• when、interval 和 atTime：共同决定何时创建新日志文件
• backupCount：保留多少份旧日志文件
• encoding：编码
• delay：是否在第一次往文件中写日志时才打开文件，默认 False
• utc：是否使用 UTC 时间，默认 False

例如我们想要每天的凌晨 0 点创建新日志文件，文件名为 app.log，UTF-8 编码，保留最新的 7 份旧日志文件：

import logging
import logging.handlers

fh = logging.handlers.TimedRotatingFileHandler('app.log', when='midnight', backupCount=7, encoding='utf8')
logging.basicConfig(
    format="%(asctime)s %(levelname)s %(message)s",
    level=logging.DEBUG,
    datefmt="%Y-%m-%d %H:%M:%S",
    handlers=[fh],
)

logging.info("这是一条 INFO 消息。")

使用模块级的 logger

如果项目文件很多，有时我们可能希望在输出日志的同时，能够直到每条日志是由哪个文件（模块）记录的。我们可以通过模块级的日志来实现，只需要在每个模块的最上方引入如下语句创建一个 logger，并在 logging format 中加上 %(name)s 即可：

logger = logging.getLogger(__name__)

关于 __name__，根据官方文档：

A module is a file containing Python definitions and statements. The file name is the module name with the suffix .py appended. Within a module, the module’s name (as a string) is available as the value of the global variable __name__.

这样就会创建一个以该模块名命名的 logger。当然你也可以自己随便取名，只不过使用 __name__ 更方便。

然后在接下来记录日志时使用 logger.info() 等方法即可。

例如，有如下文件结构：

|app.py
|package_a
|    module_a.py

# app.py

import logging
logging.basicConfig(format='%(asctime)s - %(name)s - %(levelname)s:%(message)s')
from package_a import module_a

logger = logging.getLogger(__name__)
logger.warning('来自 app 的日志。')

# module_a.py

import logging

logger = logging.getLogger(__name__)
logger.warning('来自 module_a 的日志')

$ python app.py
2019-12-24 21:53:21,915 - package_a.module_a - WARNING:来自 module_a 的日志
2019-12-24 21:53:21,916 - __main__ - WARNING:来自 app 的日志。

使用配置文件

根据官方文档，开发者有三种方式来配置 logging：

1. 使用 Python 代码显式创建 logger、handler 和 formatter，如 logging.basicConfig()。
2. 创建一个 logging 配置文件，然后用 logging.config.fileConfig() 读取。
3. 创建一个字典形式的 logging 配置，然后传给 logging.config.dictConfig()。

使用配置文件的方法（2 和 3）相比直接在程序中显示创建（1）有一些优势，例如配置和代码分离，非开发者也可以很容易地修改配置，也方便后人维护。

logging.config.fileConfig() 只能接受 configparser 格式的 .ini 文件，例如：

[loggers]
keys=root,simpleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleExample]
level=DEBUG
handlers=consoleHandler
qualname=simpleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=

Python 3.2 加入的 logging.config.dictConfig() 使得配置 logging 的方式更加灵活，只需传入 dict 即可，而以什么文件格式定义这个 dict 不受限制，.py、.json 或者 .yml 均可。其中 .yml 格式可读性较强，像 Python 一样没有那么多符号累赘，修改起来也容易。缺点是读取 .yml 文件需要第三方的 PyYAML，而 .json 则有内置的标准库 json。

此处以 .yml 为例，说明如何用 logging.config.dictConfig() 来配置 logging。

假设我们有如下需求：

• 日志同时输出到终端和文件，终端采用 StreamHandler，志等级为 INFO。文件采用 TimedRotatingFileHandler，每天凌晨 rollover，UTF8 编码，文件名为 app.log，日志等级为 DEBUG
• 日志格式为 %(asctime)s - %(name)s - %(levelname)s: %(message)s
• 使用模块级 logger

那可以编写如下配置文件：

# logging_config.yml

version: 1

formatters:
  default:
    format: "%(asctime)s - %(name)s - %(levelname)s: %(message)s"

handlers:
  console:
    class: logging.StreamHandler
    level: INFO
    formatter: default

  file:
    class: logging.handlers.TimedRotatingFileHandler
    level: DEBUG
    filename: log/app.log
    when: midnight
    encoding: utf-8
    formatter: default

loggers:
  app:
    handlers: [console, file]
    level: DEBUG
  package_a.module_a:
    handlers: [console, file]
    level: DEBUG

disable_existing_loggers: false

下面我分别解释下：

• version：int 类型，必有参数，目前的可用值只有 1
• formatters：指定日志格式
• handlers：可定义多个 handler，每个 handler 都有一个名字，可以在下文使用，如例子中的 console 和 file。每个 handler 都有自己的类型，使用 class 指定，例如 logging.StreamHandler，每种类型的参数可以直接用 key: value 的方式直接指定
• loggers：和 handlers 结构类似，指定多个 logger。这里需要注意的是，logger 是有层级的，以 . 分隔，与 Python 的 import 机制类似。所以会出现 package_a.module_a 这种名字，但是实际上我们在代码种创建 logger 时是不必这么写的，直接用 __name__ 就行
• disable_existing_loggers：默认为 true，禁用已存在的 logger。fileConfig 和 dictConfig 默认都会如此，如果你发现有的日志应该出现但是没有出现，可将此设为 false，如 gunicorn 就会默认被禁用，详情可参见 gunicorn accesslog 为空的一种可能解决办法

然后在 app.py 程序中使用如下语句读入配置，并删除 logging.basicConfig() 语句，然后在各个模块创建 logger 即可（完整代码见 GitHub）：

为了保持简洁，这里就不放完整代码了，完整代码放在 GitHub。

with open("logging_config.yml", "r", encoding="utf8") as f:
    logging_config = yaml.safe_load(f)
logging.config.dictConfig(logging_config)
logger = logging.getLogger('app')

注意如果使用 gunicorn 来启动 flask 服务，那么在 app.py 种使用 logger = logging.getLogger(__name__) 即可，不必写成 app。此处写成 app 是假设直接运行 python app.py 来启动程序，此时 __name__ 为 __main__，不是 app。

那么运行 python app.py 可看到终端只输出了 INFO 等级以上的日志：

$ python app.py
2019-12-29 20:20:51,231 - app - WARNING: 来自 app 的 WARNING 日志。
2019-12-29 20:20:51,232 - package_a.module_a - WARNING: 来自 module_a 的 WARNING 日志

log/app.log 输出了 DEBUG 等级以上的日志：

2019-12-29 20:20:51,231 - app - DEBUG: 来自 app 的 DEBUG 日志。
2019-12-29 20:20:51,231 - app - WARNING: 来自 app 的 WARNING 日志。
2019-12-29 20:20:51,232 - package_a.module_a - DEBUG: 来自 module_a 的 DEBUG 日志
2019-12-29 20:20:51,232 - package_a.module_a - WARNING: 来自 module_a 的 WARNING 日志

如果程序运行时间超过一天，便可以看到 log/ 下会有类似 app.log.2019-12-28 的日志文件，后面会以日期结尾。

总结

总结起来，就是以下几点：

• 按照自己的要求格式化日志
• 设置恰当的日志等级
• 使用恰当的日志等级
• 记录 traceback
• 日志输出到文件，且使用 RotatingFileHandler 或者 TimedRotatingFileHandler
• 使用模块级的 logger
• 使用配置文件来设置 logging

Reference

• logging — Logging facility for Python — Python 3.8.1rc1 documentation
• Logging HOWTO — Python 3.8.1rc1 documentation
• python - What is the default handler for the child logger? - Stack Overflow
• gunicorn accesslog 为空的一种可能解决办法_Alan Lee-CSDN博客
• logging - When to use the different log levels - Stack Overflow