Pytest如何输出Log信息

自动化测试用例的调试信息非常有用，可以让我们知道现在的运行情况到，执行到哪步以及相应的出错信息等，可以在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信息。

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 212,185评论 6赞 493
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 90,445评论 3赞 385
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 157,684评论 0赞 348
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 56,564评论 1赞 284
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 65,681评论 6赞 386
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 49,874评论 1赞 290
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 39,025评论 3赞 408
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,761评论 0赞 268
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 44,217评论 1赞 303
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,545评论 2赞 327
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,694评论 1赞 341
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 34,351评论 4赞 332
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,988评论 3赞 315
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,778评论 0赞 21
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,007评论 1赞 266
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 46,427评论 2赞 360
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 43,580评论 2赞 349

推荐阅读更多精彩内容

  • Spring Cloud
    Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具（例如配置管理，服务发现，断路器，智...
    卡卡罗2017阅读 134,633评论 18赞 139
  • Spring boot参考指南
    Spring Boot 参考指南 介绍 转载自:https://www.gitbook.com/book/qbgb...
    毛宇鹏阅读 46,778评论 6赞 342
  • 无标题文章
    spring官方文档：http://docs.spring.io/spring/docs/current/spri...
    牛马风情阅读 1,653评论 0赞 3
  • Android - 收藏集
    Android 自定义View的各种姿势1 Activity的显示之ViewRootImpl详解 Activity...
    passiontim阅读 171,810评论 25赞 707
  • 花王屁股
    还在用花王滴宝妈们看一下吧 [发呆][发呆] 所谓花王屁股 [咖啡]解读一下所谓的"花王屁股"[得意][得意] 为...
    猴哥妈妈阅读 1,689评论 0赞 7