Table of Contents
There are many circumstances where it’s really great to display the print statements and logging from a test while a test is running, and not wait until the end.
Printing and logging in test code
Before you pipe in with “unit tests should be fast”, I’ll just remind you that pytest can be used for system tests, performance tests, and other long running tests, and can be used to test both software and hardware.
Debug print and logging statements are great for letting me know whats going on during execution. But when I put print or logging into test code, it gets captured and hidden for passing tests.
That’s a good thing perhaps most of the time.
However, sometimes I want to get around it.
I’ll show a couple of examples of what I’m talking about below, and show how I solve it.
Example with print statements
Let’s start with a couple simple tests that take 3+ seconds each to run.
test_slow_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'
If I just run this normally, pytest will capture all of the output, save it until all of the tests are finished, and display output from the failing tests.
$ pytest --tb=short test_slow_print.py
================ test session starts ================
collected 2 items
test_slow_print.py .F [100%]
===================== FAILURES ======================
______________________ test_2 _______________________
test_slow_print.py:21: in test_2
assert 0, 'failing for demo purposes'
E AssertionError: failing for demo purposes
E assert 0
--------------- Captured stdout call ----------------
in test_2
after 1 sec
after 2 sec
after 3 sec
============== short test summary info ==============
FAILED test_slow_print.py::test_2 - AssertionError: failing for demo purposes
============ 1 failed, 1 passed in 6.06s ============
Using -s or --capture=no for print statements
I can use the ‘-s’ flag, or ‘–capture=no’, and then all of the output is reported. And, as a bonus, the output happens during the test run.
$ pytest --tb=short -s test_slow_print.py
================ test session starts ================
collected 2 items
test_slow_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 _______________________
test_slow_print.py:21: in test_2
assert 0, 'failing for demo purposes'
E AssertionError: failing for demo purposes
E assert 0
============== short test summary info ==============
FAILED test_slow_print.py::test_2 - AssertionError: failing for demo purposes
============ 1 failed, 1 passed in 6.06s ============
Example with logging
Logging using the standard logging module is handled differently by pytest.
Let’s replace the print statements with logging statements.
test_slow_log.py
import time
import logging
logging.basicConfig(level=logging.DEBUG)
def test_1(caplog):
caplog.set_level(logging.DEBUG)
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(caplog):
caplog.set_level(logging.DEBUG)
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'
Here’s the output.
$ pytest --tb=short test_slow_log.py
================ test session starts ================
collected 2 items
test_slow_log.py .F [100%]
===================== FAILURES ======================
______________________ test_2 _______________________
test_slow_log.py:26: in test_2
assert 0, 'failing for demo purposes'
E AssertionError: failing for demo purposes
E assert 0
----------------- Captured log call -----------------
DEBUG test_2:test_slow_log.py:21 after 1 sec
DEBUG test_2:test_slow_log.py:23 after 2 sec
DEBUG test_2:test_slow_log.py:25 after 3 sec
============== short test summary info ==============
FAILED test_slow_log.py::test_2 - AssertionError: failing for demo purposes
============ 1 failed, 1 passed in 6.07s ============
Like our original print problem, we don’t see the logging until the end of the test.
Unlike the print version, we cannot use -s.
Using --log-cli-level for logging statements
To see the logging in real time, we can use --log-cli-level=DEBUG.
$ pytest --tb=no --log-cli-level=DEBUG test_slow_log.py
================ test session starts ================
collected 2 items
test_slow_log.py::test_1
------------------- live log call -------------------
DEBUG test_1:test_slow_log.py:10 after 1 sec
DEBUG test_1:test_slow_log.py:12 after 2 sec
DEBUG test_1:test_slow_log.py:14 after 3 sec
PASSED [ 50%]
test_slow_log.py::test_2
------------------- live log call -------------------
DEBUG test_2:test_slow_log.py:21 after 1 sec
DEBUG test_2:test_slow_log.py:23 after 2 sec
DEBUG test_2:test_slow_log.py:25 after 3 sec
FAILED [100%]
============== short test summary info ==============
FAILED test_slow_log.py::test_2 - AssertionError: failing for demo purposes
============ 1 failed, 1 passed in 6.04s ============
Now the output is coming out as the test is running. Excellent.