在pytest测试中记录日志

Question

我想在测试函数里加一些日志语句，以便检查一些状态变量。

我有以下这段代码：

import pytest,os
import logging

logging.basicConfig(level=logging.DEBUG)
mylogger = logging.getLogger()

#############################################################################

def setup_module(module):
    ''' Setup for the entire module '''
    mylogger.info('Inside Setup')
    # Do the actual setup stuff here
    pass

def setup_function(func):
    ''' Setup for test functions '''
    if func == test_one:
        mylogger.info(' Hurray !!')

def test_one():
    ''' Test One '''
    mylogger.info('Inside Test 1')
    #assert 0 == 1
    pass

def test_two():
    ''' Test Two '''
    mylogger.info('Inside Test 2')
    pass

if __name__ == '__main__':
    mylogger.info(' About to start the tests ')
    pytest.main(args=[os.path.abspath(__file__)])
    mylogger.info(' Done executing the tests ')

我得到了以下输出：

[bmaryada-mbp:/Users/bmaryada/dev/platform/main/proto/tests/tpch $]python minitest.py
INFO:root: About to start the tests 
======================================================== test session starts =========================================================
platform darwin -- Python 2.6.2 -- pytest-2.0.0
collected 2 items 

minitest.py ..

====================================================== 2 passed in 0.01 seconds ======================================================
INFO:root: Done executing the tests 

注意到只有来自 '__name__ == __main__' 这个块的日志信息被显示到了控制台上。

有没有办法强制 pytest 也把测试方法里的日志信息输出到控制台呢？

Answer 1

使用 pytest --log-cli-level=DEBUG 这个命令在pytest中运行是没问题的（我测试过的版本从6.2.2到7.1.1都可以）。

如果你使用 pytest --log-cli-level=DEBUG --capture=tee-sys，那么它还会打印出 stdtout 的内容。

Answer 2

从3.3版本开始，pytest支持实时日志记录，这意味着在测试中产生的所有日志信息会立即显示在终端上。这个功能的详细说明可以在实时日志部分找到。默认情况下，实时日志是关闭的；要开启它，你需要在pyproject.toml¹或pytest.ini²配置文件中设置log_cli = 1。实时日志支持将日志输出到终端和文件；相关选项可以自定义日志记录的格式：

终端：

• log_cli_level
• log_cli_format
• log_cli_date_format

文件：

• log_file
• log_file_level
• log_file_format
• log_file_date_format

正如Kévin Barré在这条评论中指出的，可以通过命令行覆盖ini选项，方法是：

-o OVERRIDE_INI, --override-ini=OVERRIDE_INI
        使用"option=value"的格式覆盖ini选项，例如：
        -o xfail_strict=True -o cache_dir=cache

所以，你可以不在pytest.ini中声明log_cli，而是直接调用：

$ pytest -o log_cli=true ...

示例

这是一个简单的测试文件，用于演示：

# test_spam.py

import logging

LOGGER = logging.getLogger(__name__)


def test_eggs():
    LOGGER.info('eggs info')
    LOGGER.warning('eggs warning')
    LOGGER.error('eggs error')
    LOGGER.critical('eggs critical')
    assert True

如你所见，不需要额外的配置；pytest会根据pytest.ini中指定的选项或从命令行传递的选项自动设置日志记录器。

实时日志到终端，INFO级别，漂亮的输出

在pyproject.toml中的配置：

[tool.pytest.ini_options]
log_cli = true
log_cli_level = "INFO"
log_cli_format = "%(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)"
log_cli_date_format = "%Y-%m-%d %H:%M:%S"

在传统的pytest.ini中的相同配置：

[pytest]
log_cli = 1
log_cli_level = INFO
log_cli_format = %(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)
log_cli_date_format=%Y-%m-%d %H:%M:%S

运行测试：

$ pytest test_spam.py
=============================== test session starts ================================
platform darwin -- Python 3.6.4, pytest-3.7.0, py-1.5.3, pluggy-0.7.1 -- /Users/hoefling/.virtualenvs/stackoverflow/bin/python3.6
cachedir: .pytest_cache
rootdir: /Users/hoefling/projects/private/stackoverflow/so-4673373, inifile: pytest.ini
collected 1 item

test_spam.py::test_eggs
---------------------------------- live log call -----------------------------------
2018-08-01 14:33:20 [    INFO] eggs info (test_spam.py:7)
2018-08-01 14:33:20 [ WARNING] eggs warning (test_spam.py:8)
2018-08-01 14:33:20 [   ERROR] eggs error (test_spam.py:9)
2018-08-01 14:33:20 [CRITICAL] eggs critical (test_spam.py:10)
PASSED                                                                        [100%]

============================= 1 passed in 0.01 seconds =============================

实时日志到终端和文件，终端只显示消息和CRITICAL级别，pytest.log文件中有漂亮的输出

在pyproject.toml中的配置：

[tool.pytest.ini_options]
log_cli = true
log_cli_level = "CRITICAL"
log_cli_format = "%(message)s"

log_file = "pytest.log"
log_file_level = "DEBUG"
log_file_format = "%(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)"
log_file_date_format = "%Y-%m-%d %H:%M:%S"

在传统的pytest.ini中的相同配置：

[pytest]
log_cli = 1
log_cli_level = CRITICAL
log_cli_format = %(message)s

log_file = pytest.log
log_file_level = DEBUG
log_file_format = %(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)
log_file_date_format=%Y-%m-%d %H:%M:%S

测试运行：

$ pytest test_spam.py
=============================== test session starts ================================
platform darwin -- Python 3.6.4, pytest-3.7.0, py-1.5.3, pluggy-0.7.1 -- /Users/hoefling/.virtualenvs/stackoverflow/bin/python3.6
cachedir: .pytest_cache
rootdir: /Users/hoefling/projects/private/stackoverflow/so-4673373, inifile: pytest.ini
collected 1 item

test_spam.py::test_eggs
---------------------------------- live log call -----------------------------------
eggs critical
PASSED                                                                        [100%]

============================= 1 passed in 0.01 seconds =============================

$ cat pytest.log
2018-08-01 14:38:09 [    INFO] eggs info (test_spam.py:7)
2018-08-01 14:38:09 [ WARNING] eggs warning (test_spam.py:8)
2018-08-01 14:38:09 [   ERROR] eggs error (test_spam.py:9)
2018-08-01 14:38:09 [CRITICAL] eggs critical (test_spam.py:10)

---

¹ pyproject.toml从6.0版本开始支持，我认为这是最好的选择。有关规格，请参见PEP 518。

² 虽然你也可以在setup.cfg的[tool:pytest]部分配置pytest，但如果你想提供自定义的实时日志格式，最好不要这样做。其他读取setup.cfg的工具可能会将%(message)s视为字符串插值，从而导致失败。总之，使用pyproject.toml是最好的选择，但如果你被迫使用传统的ini格式，最好坚持使用pytest.ini以避免错误。

Answer 3

对我来说是有效的，以下是我得到的输出：[省略 -> 示例不正确]

补充一下：似乎你需要在运行py.test时加上 -s 这个选项，这样它就不会捕捉标准输出了。在这里（py.test没有安装），只需要用 python pytest.py -s pyt.py 就可以了。

对于你的代码，你只需要在 main 的 args 中加上 -s：

 pytest.main(args=['-s', os.path.abspath(__file__)])

可以查看py.test的文档，了解更多关于 捕捉输出 的内容。