pytest debug print logging in real time

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

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.

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.

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

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.

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.

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:

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.

Comments

  1. says

    On Debian (wheezy), when I run the second example (–capture=no), I see the print output immediately, interspersed within the “dots” (in this case a dot and an F) or within test name:line number/PASSED/FAILED.

    • says

      Hmmm. Well, cool. I guess you don’t need to worry about using logging then.

      Thanks for letting me know.

      I’ve tried it again.
      I’m using windows 7.

      Python 2.7, pytest 2.3.4.
      From Cygwin bash, no immediate output.
      From cmd (dos prompt), I do see immediate output.

      I’m guessing it’s then either Cygwin or bash that’s messing it up for me.

      • says

        Just tested this on OSX bash.
        The ‘-s’ option is sufficient with print as well as logging.
        I’ll have to update the post soon.
        Cool.

  2. says

    On the final question, I don’t have a systematic method to add a newline, but if the interspersed output becomes bothersome, it’s easy enough to change the first “print whatever” to “print ‘\n’, whatever”.

  3. says

    Just saw a new plugin today which may help: https://pypi.python.org/pypi/pytest-instafail/0.1.0

    If you need more it seems the guy who released it is taking issues and suggestions.

    In any case I agree with the plugin writer that extending TerminalReporter is a good thing to do here.

    Also, i guess you are aware that you could add “–instafail” to your “[pytest] addopts” pytest.ini/setup.cfg file to make it permanent.

  4. says

    I have the exact same problem with OSX bash with logging. There is no newline for the dot and it appears just before the log of the next test ;(
    Did you make it work with OSX bash?

    • says

      antoinet,
      I had forgotten about that little annoyance.
      When running ‘-s’, I get the behavior your describing.
      I’m still holding out hope that it can be fixed. Perhaps in a plugin.
      If I find a solution, I’ll let you know.

Leave a Reply