Pytest中文文档

Pytest如何输出Log信息

2017-03-18  本文已影响1692人  Yating_Yang

自动化测试用例的调试信息非常有用，可以让我们知道现在的运行情况到，执行到哪步以及相应的出错信息等，可以在pytest里面，有时并不会输出所有信息，比如默认情况下pass的测试用例是没有print输出的。本文将介绍如何在pytest里面实时显示所有的log信息。

1. 用print输出log信息

slowTest_print.py

import time
 
def test_1():
    print 'test_1'
    time.sleep(1)
    print 'after 1 sec'
    time.sleep(1)
    print 'after 2 sec'
    time.sleep(1)
    print 'after 3 sec'
    assert 1, 'should pass'
 
def test_2():
    print 'in test_2'
    time.sleep(1)
    print 'after 1 sec'
    time.sleep(1)
    print 'after 2 sec'
    time.sleep(1)
    print 'after 3 sec'
    assert 0, 'failing for demo purposes'

运行上述程序，pytest会capture所有的输出，保存直到所有的测试用例都执行结束，并且只输出那些失败的测试用例的信息，对于成功的测试用例，没有print的信息显示。
从下面的运行结果，如果需要查看test_1()的运行情况，没有log信息可看，print没有显示。

C:\Users\yatyang\PycharmProjects\pytest_example>pytest -v slowTest_print.py
============================= test session starts =============================
platform win32 -- Python 2.7.13, pytest-3.0.6, py-1.4.32, pluggy-0.4.0 -- C:\Python27\python.exe
cachedir: .cache
metadata: {'Python': '2.7.13', 'Platform': 'Windows-7-6.1.7601-SP1', 'Packages': {'py': '1.4.32', 'pytest': '3.0.6', 'pluggy': '0.4.0'}, 'JAVA_HOME': 'C:\\Program Files (x86)\\Java\\jd
k1.7.0_01', 'Plugins': {'html': '1.14.2', 'metadata': '1.3.0'}}
rootdir: C:\Users\yatyang\PycharmProjects\pytest_example, inifile:
plugins: metadata-1.3.0, html-1.14.2
collected 2 items 

slowTest_print.py::test_1 PASSED
slowTest_print.py::test_2 FAILED

================================== FAILURES ===================================
___________________________________ test_2 ____________________________________

    def test_2():
        print 'in test_2'
        time.sleep(1)
        print 'after 1 sec'
        time.sleep(1)
        print 'after 2 sec'
        time.sleep(1)
        print 'after 3 sec'
>       assert 0, 'failing for demo purposes'
E       AssertionError: failing for demo purposes
E       assert 0

slowTest_print.py:22: AssertionError
---------------------------- Captured stdout call -----------------------------
in test_2
after 1 sec
after 2 sec
after 3 sec
===================== 1 failed, 1 passed in 6.45 seconds ======================

C:\Users\yatyang\PycharmProjects\pytest_example>

我们可以用‘-s’参数或者 ‘–capture=no’，这样就可以输出所有测试用的print信息。但是pytest还是会等着所有的测试用例都执行完毕才会显示运行结果。可以看到下面的test_1也显示出print的相关信息。

C:\Users\yatyang\PycharmProjects\pytest_example>py.test --capture=no slowTest_print.py
============================= test session starts =============================
platform win32 -- Python 2.7.13, pytest-3.0.6, py-1.4.32, pluggy-0.4.0
metadata: {'Python': '2.7.13', 'Platform': 'Windows-7-6.1.7601-SP1', 'Packages': {'py': '1.4.32', 'pytest': '3.0.6', 'pluggy': '0.4.0'}, 'JAVA_HOME': 'C:\\Program Files (x86)\\Java\\jd
k1.7.0_01', 'Plugins': {'html': '1.14.2', 'metadata': '1.3.0'}}
rootdir: C:\Users\yatyang\PycharmProjects\pytest_example, inifile:
plugins: metadata-1.3.0, html-1.14.2
collected 2 items 

slowTest_print.py test_1
after 1 sec
after 2 sec
after 3 sec
.in test_2
after 1 sec
after 2 sec
after 3 sec
F

================================== FAILURES ===================================
___________________________________ test_2 ____________________________________

    def test_2():
        print 'in test_2'
        time.sleep(1)
        print 'after 1 sec'
        time.sleep(1)
        print 'after 2 sec'
        time.sleep(1)
        print 'after 3 sec'
>       assert 0, 'failing for demo purposes'
E       AssertionError: failing for demo purposes
E       assert 0

slowTest_print.py:22: AssertionError
===================== 1 failed, 1 passed in 6.17 seconds ======================

2. Python Logging用法

一般情况下，一些程序的调试过程中我们会让它输出一些信息，特别是一些大型的程序，我们通过这些信息可以了解程序的运行情况，python提供了一个日志模块logging，它可以把我们想要的信息全部保存到一个日志文件中，方便查看。

import logging

logging.debug('This is debug message')
logging.info('This is info message')
logging.warning('This is warning message')

屏幕上打印:
WARNING:root:This is warning message
默认情况下，logging将日志打印到屏幕，日志级别为WARNING；
日志级别大小关系为：CRITICAL > ERROR > WARNING > INFO > DEBUG > NOTSET，当然也可以自己定义日志级别。

3. 在pytest中用logging代替print

我们现在来看看在pytest的测试用例里面用logging的输出代替print，有什么不同。
slowTest_logging.py

import time
import logging

logging.basicConfig(level=logging.DEBUG)

def test_1():
    log = logging.getLogger('test_1')
    time.sleep(1)
    log.debug('after 1 sec')
    time.sleep(1)
    log.debug('after 2 sec')
    time.sleep(1)
    log.debug('after 3 sec')
    assert 1, 'should pass'


def test_2():
    log = logging.getLogger('test_2')
    time.sleep(1)
    log.debug('after 1 sec')
    time.sleep(1)
    log.debug('after 2 sec')
    time.sleep(1)
    log.debug('after 3 sec')
    assert 0, 'failing for demo purposes'

运行结果如下,log信息的显示是不是可读性更好了呢。可是pytest还是要等所有的结果都运行完毕才完全输出到屏幕上，没法看到实时的运行情况。比如现在要测试一个新的image，不知道quality如何，如果测试用例非常多，测试人员就得一直等，也许前面的一些测试用都失败就可以停止执行了。那怎么实现实时显示呢？请看方法4。

C:\Users\yatyang\PycharmProjects\pytest_example>pytest slowTest_logging.py
============================= test session starts =============================
platform win32 -- Python 2.7.13, pytest-3.0.6, py-1.4.32, pluggy-0.4.0
metadata: {'Python': '2.7.13', 'Platform': 'Windows-7-6.1.7601-SP1', 'Packages': {'py': '1.4.32', 'pytest': '3.0.6', 'pluggy': '0.4.0'}, 'JAVA_HOME': 'C:\\Program Files (x86)\\Java\\jd
k1.7.0_01', 'Plugins': {'html': '1.14.2', 'metadata': '1.3.0'}}
rootdir: C:\Users\yatyang\PycharmProjects\pytest_example, inifile:
plugins: metadata-1.3.0, html-1.14.2
collected 2 items 

slowTest_logging.py .F

================================== FAILURES ===================================
___________________________________ test_2 ____________________________________

    def test_2():
        log = logging.getLogger('test_2')
        time.sleep(1)
        log.debug('after 1 sec')
        time.sleep(1)
        log.debug('after 2 sec')
        time.sleep(1)
        log.debug('after 3 sec')
>       assert 0, 'failing for demo purposes'
E       AssertionError: failing for demo purposes
E       assert 0

slowTest_logging.py:25: AssertionError
---------------------------- Captured stderr call -----------------------------
DEBUG:test_2:after 1 sec
DEBUG:test_2:after 2 sec
DEBUG:test_2:after 3 sec
===================== 1 failed, 1 passed in 6.37 seconds ======================

C:\Users\yatyang\PycharmProjects\pytest_example>pytest -s slowTest_logging.py
============================= test session starts =============================
platform win32 -- Python 2.7.13, pytest-3.0.6, py-1.4.32, pluggy-0.4.0
metadata: {'Python': '2.7.13', 'Platform': 'Windows-7-6.1.7601-SP1', 'Packages': {'py': '1.4.32', 'pytest': '3.0.6', 'pluggy': '0.4.0'}, 'JAVA_HOME': 'C:\\Program Files (x86)\\Java\\jd
k1.7.0_01', 'Plugins': {'html': '1.14.2', 'metadata': '1.3.0'}}
rootdir: C:\Users\yatyang\PycharmProjects\pytest_example, inifile:
plugins: metadata-1.3.0, html-1.14.2
collected 2 items 

slowTest_logging.py DEBUG:test_1:after 1 sec
DEBUG:test_1:after 2 sec
DEBUG:test_1:after 3 sec
.DEBUG:test_2:after 1 sec
DEBUG:test_2:after 2 sec
DEBUG:test_2:after 3 sec
F

================================== FAILURES ===================================
___________________________________ test_2 ____________________________________

    def test_2():
        log = logging.getLogger('test_2')
        time.sleep(1)
        log.debug('after 1 sec')
        time.sleep(1)
        log.debug('after 2 sec')
        time.sleep(1)
        log.debug('after 3 sec')
>       assert 0, 'failing for demo purposes'
E       AssertionError: failing for demo purposes
E       assert 0

slowTest_logging.py:25: AssertionError
===================== 1 failed, 1 passed in 6.18 seconds ======================

4. pytest用logging和--capture=no实现实时输出log信息

请自己去运行下面的程序吧，可以看到该程序是实时输出当前测试用例执行的情况。

C:\Users\yatyang\PycharmProjects\pytest_example>pytest -s slowTest_logging.py
============================= test session starts =============================
platform win32 -- Python 2.7.13, pytest-3.0.6, py-1.4.32, pluggy-0.4.0
metadata: {'Python': '2.7.13', 'Platform': 'Windows-7-6.1.7601-SP1', 'Packages': {'py': '1.4.32', 'pytest': '3.0.6', 'pluggy': '0.4.0'}, 'JAVA_HOME': 'C:\\Program Files (x86)\\Java\\jd
k1.7.0_01', 'Plugins': {'html': '1.14.2', 'metadata': '1.3.0'}}
rootdir: C:\Users\yatyang\PycharmProjects\pytest_example, inifile:
plugins: metadata-1.3.0, html-1.14.2
collected 2 items 

slowTest_logging.py DEBUG:test_1:after 1 sec
DEBUG:test_1:after 2 sec
DEBUG:test_1:after 3 sec
.DEBUG:test_2:after 1 sec
DEBUG:test_2:after 2 sec
DEBUG:test_2:after 3 sec
F

================================== FAILURES ===================================
___________________________________ test_2 ____________________________________

    def test_2():
        log = logging.getLogger('test_2')
        time.sleep(1)
        log.debug('after 1 sec')
        time.sleep(1)
        log.debug('after 2 sec')
        time.sleep(1)
        log.debug('after 3 sec')
>       assert 0, 'failing for demo purposes'
E       AssertionError: failing for demo purposes
E       assert 0

slowTest_logging.py:25: AssertionError
===================== 1 failed, 1 passed in 6.20 seconds ======================

5.总结

在写自动化测试用例时，添加有用的log信息是非常有必要的。比如在初期的调试过程，能够一旦运行有问题，就可以获取到精确的调试信息。后期在稳定的运行中，其他测试人员来运行也可以很容易上手，所以大家一定要重视测试用例的调试信息。
通过本文，应该知道如何用pytest，logging和--capture=no实现运行测试用例的实时输出所有的log信息。

上一篇下一篇

猜你喜欢

热点阅读