将py.test的日志信息和测试结果/断言记录到一个文件中

Question

我现在开始为一个新项目使用py.test。我们正在配置Linux服务器，我需要写一个脚本来检查这些服务器的设置和配置。我觉得py.test是实现这些测试的好方法，到目前为止，它运行得还不错。

我现在面临的问题是，我需要在这些测试结束时生成一个日志文件，里面显示每个测试的日志信息和测试结果。为了记录日志信息，我使用了logger：

logging.basicConfig(filename='config_check.log', level=logging.INFO)
pytest.main()
logging.info('all done')

作为一个示例测试，我有这个：

def test_taintedKernel():
    logging.info('checking for tainted kernel')
    output = runcmd('cat /proc/sys/kernel/tainted')
    assert output == '0', 'tainted kernel found'

所以在我的日志文件中，我希望看到这样的输出：

INFO:root:checking for tainted kernel
ERROR:root:tainted kernel found
INFO:root:next test
INFO:root:successful
INFO:root:all done

但是我无法将测试结果写入日志文件，反而在测试结束后，我在标准输出上得到了默认的输出：

======================================= test session starts =======================================
platform linux2 -- Python 2.6.8 -- py-1.4.22 -- pytest-2.6.0
collected 14 items 

test_basicLinux.py .............F

============================================ FAILURES =============================================
_______________________________________ test_taintedKernel ________________________________________

    def test_taintedKernel():
        logging.info('checking for tainted kernel')
        output = runcmd('cat /proc/sys/kernel/tainted')
>       assert output == '0', 'tainted kernel found'
E       AssertionError: tainted kernel found

test_basicLinux.py:107: AssertionError
=============================== 1 failed, 13 passed in 6.07 seconds ===============================

这可能会让我的脚本用户感到困惑。我尝试了解logger和pytest_capturelog，因为这里经常提到它们，但我肯定是做错了什么，因为我就是搞不懂。也许只是对这个是如何运作的理解不够。希望你们能给我一些提示。如果还有什么需要补充的，请告诉我。

提前感谢你们的帮助，

Stephan

Answer 1

从3.3版本开始，pytest支持实时记录日志到终端和文件。下面是一个测试模块的例子：

import logging
import os


def test_taintedKernel():
    logging.info('checking for tainted kernel')
    output = os.system('cat /proc/sys/kernel/tainted')
    assert output == 0, 'tainted kernel found'

可以在 pytest.ini 文件中配置日志记录到文件的设置：

[pytest]
log_file = my.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 session starts ========================================================
...
collected 1 item                                                                                                                   

test_spam.py .                                                                                                               [100%]

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

现在查看一下写好的日志文件：

$ cat my.log
2019-07-12 23:51:41 [    INFO] checking for tainted kernel (test_spam.py:6)

想要了解更多关于如何同时将实时日志输出到终端和日志文件的例子，可以查看我对 在 py.test 测试中记录日志 的回答。

参考资料：pytest 文档中的实时日志部分。

Answer 2

pytest的工作是捕捉输出并将其展示给操作员。所以，与其试图让pytest按照你想要的方式进行日志记录，不如把日志记录直接放到你的测试中。

Python的assert命令只需要一个真假值和一条消息。因此，在你的测试中，不妨不要直接使用简单的assert，而是可以写一个小函数，如果值为假（这也是assert失败的条件），就进行日志记录，然后再调用assert。这样你就能得到想要的日志记录，同时也能保持assert的功能，生成控制台输出。

下面是一个使用这种函数的小测试文件：

# test_foo.py
import logging

def logAssert(test,msg):
    if not test:
        logging.error(msg)
        assert test,msg

def test_foo():
    logging.info("testing foo")
    logAssert( 'foo' == 'foo', "foo is not foo")

def test_foobar():
    logging.info("testing foobar")
    logAssert( 'foobar' == 'foo', "foobar is not foo")

这是测试运行器，和你的非常相似：

# runtests.py
import logging
import pytest

logging.basicConfig(filename='config_check.log', level=logging.INFO)
logging.info('start')
pytest.main()
logging.info('done')

这是输出结果：

# python runtests.py
==== test session starts ========================
platform linux2 -- Python 2.6.6 -- py-1.4.22 -- pytest-2.6.0
collected 2 items

test_foo.py .F

========== FAILURES ============================
________ test_foobar __________________________

    def test_foobar():
        logging.info("testing foobar")
>       logAssert( 'foobar' == 'foo', "foobar is not foo")

test_foo.py:14:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

test = False, msg = 'foobar is not foo'

    def logAssert(test,msg):
        if not test:
            logging.error(msg)
>           assert test,msg
E           AssertionError: foobar is not foo

test_foo.py:6: AssertionError    ==== 1 failed, 1 passed in 0.02 seconds =======

这是生成的日志：

# cat config_check.log 
INFO:root:start
INFO:root:testing foo
INFO:root:testing foobar
ERROR:root:foobar is not foo
INFO:root:done