Capturing, with and without stdlib logging

[SwampFalc]

So I find myself rather confused by output capturing.

Let's start by quoting the manual:

def test_myoutput(capsys): # or use "capfd" for fd-level
    print ("hello")
    sys.stderr.write("world\n")
    out, err = capsys.readouterr()
    assert out == "hello\n"
    assert err == "world\n"
    print ("next")
    out, err = capsys.readouterr()
    assert out == "next\n"

I run this with pytest test_me.py and I get a pass.

Then I run this with pytest -s test_me.py, and I still get a pass. Which according to the manual doesn't make sense. -s is described as disabling capturing. So either I'm not grasping something crucial, or the manual is wrong, or there's a bug in the implementation of -s.

I then become even more confused when I try to test the behaviour of the stdlib logging module. I don't mean testing the module, but testing that my app emits the right log entries in the right circumstances.

So I make this example code:

import sys
import logging

logger = logging.getLogger()
logger.setLevel(logging.INFO)
handler = logging.StreamHandler(sys.stdout)
logger.addHandler(handler)

def test_myoutput(capsys):
    logger.error('something')
    out, err = capsys.readouterr()
    with capsys.disabled():
        print 'E:' + err
        print 'O:' + out

I run this without -s:

E:
O:

Then I run it with -s:

something
E:
O:

So at first sight this makes some sense. The logging output happens, it just gets captured somewhere, unless I specify -s. So in this case -s does seem to work exactly as described, the only remaining issue is that capsys for some reason doesn't capture what logging emits on sys.stdout...

So we do the obvious next step and replace all occurrences of capsys with capfd!

Run without -s:

E:
O:

Run with -s:

E:
O: something

... What? Without -s the logging output still vanishes into thin air, but now it has actually been captured with -s? So in this case the flag actually turns capturing on, when the description is that it turns capturing off?

Could someone explain what I'm missing here, or what I'm doing wroing?

(I'm aware I could reconfigure my logger so that it goes to a file or something and avoid this, but I'd prefer to stick as closely as possible to my production code)

[nicoddemus]

Which according to the manual doesn't make sense. -s is described as disabling capturing. So either I'm not grasping something crucial, or the manual is wrong, or there's a bug in the implementation of -s.

-s disables general output capturing of sys.stdout and sys.stderr, but doesn't really have effect on capsys or capfd. Those fixtures will always capture output, otherwise tests which use those fixtures would fail if users pass -s on the command line, which is not desired.

I then become even more confused when I try to test the behaviour of the stdlib logging module.

I will try to explain what's happening.

First, let's remember that -s is a shortcut to --capture=no. Other possible values are fd and sys with fd being the default, so not passing s means --capture=fd. I will use --capture to try to explain what's happening because it is clear than "with/without -s". Also I will only talk about sys.stdout below, but all the points are valid for sys.stderr as well.

The problem is that your example is configuring logging at the module level. What's happening is this:

1. When pytest starts with --capture=fd, it will replace sys.stdout's file descriptor by a separate file stream, say stream_a.
2. When your module is collected, you configure your logger at the module level so the logger will write to stream_a.
3. Your test starts and capsys is created. capsys will then redirect sys.stdout to a temporary file by using the "sys" method (which just changes the sys.stdout reference to another file). Let's call that file stream_b.

That's why you don't see "something" on your test, the contents of logger.error('something') is going to stream_a. When you pass --capture=no, no stream redirection occurs and you see everything that is printed by modules and tests.

Your capfd example has the same problem, because capfd will also redirect the streams, only using the fd method instead which works at the C level and extensions.

All boils down to the fact that you are configuring the module at the module level, which I know is standard practice. Unfortunately I'm not sure how you can use capsys and capfd to capture logging for you.

I suggest that you use the pytest-catchlog instead, which provides a caplog fixture that helps you check what has been loggged.

[SwampFalc]

Thank you first and foremost for pointing me to pytest-catchlog, I will see if that can solve my issue.

As for the confusion about capturing...

Thank you for explaining that 'capturing' in the context of the command-line flags, and 'capturing' in the context of capsys/capfd, are two wholly distinct and separate things.

Perhaps some terminology changes could be made to prevent such confusion for other users? In the context of the command-line flags, I feel the term 'echoing' could be used: the user chooses whether he wants to have the actual stderr/stdout output of his command echoed in pytest's output or not, and if yes through what mechanism.

[nicoddemus]

How about adding a note about it in the capture page explaining the distinction? A PR would be most welcome. 😁

Closing this for now then, feel free to reopen if you feel otherwise.