There are many circumstances where it’s really great to display the output of a test while a test is running, and not wait until the end.
In this post, I’m going to describe my method for getting around pytest’s output capture mechanism, so that I can see my debug print/logging statements in real time.
Fast and Quick? Not always
Unit tests should run fast so the entire test suite can be run quickly.
But what’s the definition of a unit test?
And what is “fast” and “quickly” exactly?
And what if I’m not really running traditional unit tests, but more “functionality units” or “feature units”?
And what if I’m what I’m really testing is the entire system, with communication delays, hardware settling times, measurement acquisition times, and who knows what all other latencies are in the system.
There are a lot of tests that are great to run from a unit test framework that don’t match the traditional definition of a fast unit test.
I’ve got tests that run for many minutes.
And suites that run for an hour and a half or more.
And during that time, I want to know what’s going on.
Debug status statements are great for letting me know whats going on during execution.
They work great in normal non-test python code.
But when I put print or logging statements into test code, it gets captured and hidden.
That’s a good thing perhaps most of the time.
I think it was a good decision to make this the default behavior.
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 of slow tests, using print statements
Let’s start with a couple simple tests that take 3+ seconds each to run.
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'
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.
> py.test slowTest_print.py
============================= test session starts ==============================
platform win32 -- Python 2.7.3 -- pytest-2.3.4
collected 2 items
slowTest_print.py .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
slowTest_print.py:26: AssertionError
------------------------------- Captured stdout --------------------------------
in test_2
after 1 sec
after 2 sec
after 3 sec
====================== 1 failed, 1 passed in 6.02 seconds ======================
I can use the ‘-s’ flag, or ‘–capture=no’, and then all of the output is reported.
However, pytest still waits until all of the tests are done to display the results.
As far as I know, there’s no way to get around it using ‘print’ statements.
Update: This apparently is an environment problem. OOPS. The ‘-s’ and ‘–capture=no’ work fine on lots of environments. The only environment I’ve seen it fail is when running tests from bash on cygwin. I should have tested it in multiple environments before posting. OOPS. Thanks to Joe for pointing this out to me.
> py.test --capture=no slowTest_print.py
============================= test session starts ==============================
platform win32 -- Python 2.7.3 -- pytest-2.3.4
collected 2 items
slowTest_print.py .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
slowTest_print.py:26: AssertionError
====================== 1 failed, 1 passed in 6.01 seconds ======================
test_1
after 1 sec
after 2 sec
after 3 sec
in test_2
after 1 sec
after 2 sec
after 3 sec
Example with logging
Logging using the standard logging module is handled differently by pytest.
Let’s replace the print statements with logging statements.
slowTest_log.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'
I’ve also set up separate named loggers for both tests.
The benefit of doing separate loggers is to make the output more readable.
Here’s the output.
> py.test slowTest_log.py
============================= test session starts ==============================
platform win32 -- Python 2.7.3 -- pytest-2.3.4
collected 2 items
slowTest_log.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
slowTest_log.py:28: AssertionError
------------------------------- Captured stderr --------------------------------
DEBUG:test_2:after 1 sec
DEBUG:test_2:after 2 sec
DEBUG:test_2:after 3 sec
====================== 1 failed, 1 passed in 6.03 seconds ======================
Well, the output is slightly nicer to read.
However, pytest is still capture the output from loggers that are writing to stdout.
Our output is still waiting for the full 6 seconds before something is reported, and the successful tests aren’t reporting their log output.
Using logging and turning capture off does the trick, almost
If we use both logging and the ‘-s’ flag (or ‘–capture=no’), then we get exactly what I want.
Almost.
> py.test -s slowTest_log.py
============================= test session starts ==============================
platform win32 -- Python 2.7.3 -- pytest-2.3.4
collected 2 items
slowTest_log.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
slowTest_log.py:28: AssertionError
====================== 1 failed, 1 passed in 6.02 seconds ======================
Now the output is coming out as the test is running. Excellent.
What’s missing?
So what’s with the “almost”? What’s missing?
Well, it’s kinda picky.
The ‘….F…F…X…’ style output is now interspersed with the logging output.
Actually, at the beginning of each test, the logging output just gets tacked onto stdout without a newline.
To be more specific about what I’d like to see. I’ll just show what my ideal output would be:
slowTest_log.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
So, the only difference that would be great would be to add a newline before the first logging statement for each test.
If anyone reading this knows how I can tell either the logging module or pytest to get those newlines in there, I’d love to hear it.