一次Pytest库升级遇到的问题

现象

公司内部的接口自动化框架在一次pytest升级后，用例中的logging模块无法正常打印日志（原来logging.info可以正常打印日志到日志文件中，现在是不会输出到对应的日志文件中）。

存在的变更：原来使用 pytest==5.4.3 版本（后续称之为低版本）的时候，升级pytest后是6.2.3版本（后续称之为高版本）。

排查过程

问题1: 为什么使用高版本的Pytest库后，日志无法打印出来呢？

先统一测试代码，发现根本原因在于：高版本Pytest场景中，logging对象的root.handlers默认存在两个Handler，直接跳过了部分处理代码，最终使用两个Handler中默认的 _FileHandler 将日志写入到了/dev/null 中了。

/dev/null ：在类Unix系统中，/dev/null，或称空设备，是一个特殊的设备文件，它丢弃一切写入其中的数据（但报告写入操作成功），读取它则会立即得到一个EOF。
在程序员行话，尤其是Unix行话中，/dev/null 被称为位桶(bit bucket)或者黑洞(black hole)。空设备通常被用于丢弃不需要的输出流，或作为用于输入流的空文件。这些操作通常由重定向完成。

而低版本Pytest场景中，logging对象的root.handlers为空，进行处理后使用的是自定义的文件目录写入日志。(可对比两者的 FileHandler 对象区别，如下两图（上图为高版本的handlers，下图为低版本），由于涉及到个人电脑目录，对低版本的日志文件路径进行了打码)

上述所述的部分处理代码如下（logging库的__init__.py文件，低版本中通过 len(root.handlers) == 0 生成了用户自定义的 FileHandler对象）：

def basicConfig(**kwargs):
  ...
  try:
    force = kwargs.pop('force', False)
    encoding = kwargs.pop('encoding', None)
    errors = kwargs.pop('errors', 'backslashreplace')
    if force:
      for h in root.handlers[:]:
        root.removeHandler(h)
        h.close()
    # 高版本的Pytest在此处logging库中直接跳到最后，最终使用的是默认的 FileHandler，将内容打印到了/dev/null
    if len(root.handlers) == 0:
      handlers = kwargs.pop("handlers", None)
      if handlers is None:
        ...

再深入一点继续往下探索！

问题2: 为什么高版本Pytest场景中，logging对象的root.handlers默认存在两个Handler？？

根本原因：高版本的Pytest对 class LoggingPlugin 类进行了修改，相关修改后导致出现该问题的代码如下（见注释部分）：

class LoggingPlugin:
    """Attaches to the logging module and captures log messages for each test."""

    def __init__(self, config: Config) -> None:
			...
      # 由于配置中未传入log_file配置，导致log_file默认为/dev/null
      log_file = get_option_ini(config, "log_file") or os.devnull
      if log_file != os.devnull:
        directory = os.path.dirname(os.path.abspath(log_file))
        if not os.path.isdir(directory):
          	os.makedirs(directory)

      # 根据默认的log_file 生成一个_FileHandler对象，最终日志被写入到了/dev/null中
      self.log_file_handler = _FileHandler(log_file, mode="w", encoding="UTF-8")
      
      # 生成另外一个 _LiveLoggingNullHandler
      self.log_cli_handler = _LiveLoggingNullHandler()

上述代码中就生成了root.handlers中的默认的两个Handler，相对于低版本中的处理逻辑如下，由于未传入log_file配置，最终生成的 log_file_handler 和 log_cli_handler 都为None，具体代码如下：

class LoggingPlugin:
    """Attaches to the logging module and captures log messages for each test.
    """

    def __init__(self, config: Config) -> None:
				...
        log_file = get_option_ini(config, "log_file")
        if log_file:
            self.log_file_handler = logging.FileHandler(
                log_file, mode="w", encoding="UTF-8"
            )  # type: Optional[logging.FileHandler]
            self.log_file_handler.setFormatter(self.log_file_formatter)
        else:
            self.log_file_handler = None

        self.log_cli_handler = None

解决方案

至此大概的解决方案思路也清晰了，通过配置对应的 log_file 配置来解决，此处有两种方式。

一种是直接写到根目录下的 pytest.ini 文件中。

1	log_file = data_factory_210517.log # 该方式比较死板，如果想修改日志文件名称需要修改pytest.ini文件

另外一种是直接通过 py.test 命令行执行的时候添加 --log-file=xxx.log（推荐）。

1	py.test --log-file=xxx.log # 可在脚本中，根据用户自定义动态生成日志文件名称

总结

大部分场景下，建议还是不要随意升级使用的组件库😭😭。。否则突然的改版可能会引起莫名其妙的问题。