capsys doesn't work correctly when you use C++ iostream from conftest

[antocuni]

The title is a bit obscure, but I think it is better explained with an example. Suppose that the following conditions are met:

1. a C++ extension which uses std::cout inside its initxxx(void) function
2. you import this extension in the conftest
3. you use --capture=fd (the default)
4. you use with capsys.disabled(): (either directly or indirectly by using --pdb)

In that case, calls to stdio.write() are not flushed automatically. The following gist includes a working example:
https://gist.github.com/antocuni/b444c2c8b37821a95f45bee42e78d3cf

To reproduce, simply run:

$ python setup.py build_ext -i
$ py.test test_noflush.py

You should be able to see the numbers 0..9 to be printed at regular intervals. However, you see them only when stdout is flushed.

Another way to see the problem is to use --pdb; using the provided gist, do the following:

py.test test_noflush.py -k test_enter_pdb --pdb
...
(Pdb) sys.stdout.write('hello\n'); time.sleep(1)
hello

Normally, you would expect to see hello while sleeping; however, because of the bug you see hello only AFTER the sleep (this happens because pdb uses readline which flushes stdout before displaying the prompt).

If you do either one of the following things, the bug disappear:

1. comment out import dummy inside conftest.py OR
2. comment out the call to std::cout inside dummy.cpp OR
3. uncomment the call to sys.stdout.flush() in test_noflush.py

Additional info:

• pip list of the virtual environment you are using

Package        Version
-------------- -------
atomicwrites   1.3.0  
attrs          19.1.0 
funcsigs       1.0.2  
more-itertools 5.0.0  
pathlib2       2.3.3  
pip            19.0.3 
pluggy         0.9.0  
py             1.8.0  
pytest         4.4.1  
scandir        1.10.0 
setuptools     41.0.0 
six            1.12.0 
wheel          0.33.1 

• pytest and operating system versions:

$ pytest --version
This is pytest version 4.4.1, imported from /tmp/yyy/local/lib/python2.7/site-packages/pytest.pyc

$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 18.04.2 LTS
Release:	18.04
Codename:	bionic

[antocuni]

Forgot to mention the python version:

$ python 
Python 2.7.15rc1 (default, Nov 12 2018, 14:31:15) 
[GCC 7.3.0] on linux2

[asottile]

capsys works at the python stream level (sys.stdout / sys.stderr) -- you're looking for capfd

See https://docs.pytest.org/en/latest/capture.html

If you want to capture on filedescriptor level you can use the capfd fixture which offers the exact same interface but allows to also capture output from libraries or subprocesses that directly write to operating system level output streams (FD1 and FD2).

[antocuni]

You are correct. However, the bug is still there even if I use capfd. I updated my gist accordingly

[asottile]

ah I see, I misread your issue and assumed you were trying to capture the c++ output.

I think maybe there's a misunderstanding here about how streams work in python, in particular the standard streams which are buffered (for performance)

Let's factor out the c++ module entirely from the situation:

import sys
import time

for i in range(10):
    sys.stdout.write('%d\n' % i)
    time.sleep(.5)

Now try the following commands:

$ python2.7 t.py
# prints the numbers one at a time every half second
$ python2.7 t.py | cat
# prints the numbers all at once
$ PYTHONUNBUFFERED=1 python2.7 t.py | cat
# back to the original behaviour

Adding a flush() makes all three invocations consistent

[antocuni]

I know about buffering, but I don't think that's not the point of the issue. Note that the issue happens only if both these three conditions are met:

1. importing a module from conftest
2. use C++ streams
3. use --capture=fd

If the problem were the buffering of sys.stdout, you would get the same behavior even without 1 or 2 or 3. I don't think there is an "easy" explanation for this behavior (or at least, I couldn't find one after spending 1 day on it). I suspect it is a bug of capfd, that's why I reported the issue here.

[antocuni]

Some more notes:

1. maybe I didn't write it very clearly, but the problem arises only if you import dummy is in the conftest; if you import it later (e.g. in test_noflush.py) it works correctly. I suppose that the difference is that in the first case, the C++ extension prints before capfd is fully initialised, or something like that.

2. I just tried and it doesn't need to be C++; a normal C extension using printf() exhibits the same behavior

[asottile]

Here's a reproduction not involving pytest:

import os
import sys
import time
import tempfile

# get fds
target = sys.stdout.fileno()
orig_fd = os.dup(target)
with tempfile.TemporaryFile() as f:
    tmp_fd = os.dup(f.fileno())

with os.fdopen(tmp_fd, 'r') as tmp:
    # start capture
    os.dup2(tmp_fd, target)

    import dummy

    sys.stdout.write('hi\n')
    sys.stdout.flush()

    # retrieve what we captured
    tmp.seek(0)
    captured = tmp.read()

# end capture
os.dup2(orig_fd, target)

# see what we captured
print(captured)

for i in range(4):
    sys.stdout.write('%d\n' % i)
    time.sleep(.5)

[antocuni]

Ok, thanks for the example; I can see that either import dummy or sys.stdout.write is enough to trigger the behavior, even if I don't understand why (if you comment out both, you see the subsequent writes immediately).

However, my point is that if pytest is able to handle correctly the import dummy at the beginning of a test file, it should also be able to handle it correctly inside a conftest.py.

The example I attached is minimal and contrived, however I have see at least one real-world case in which things started to break and/or to function differently because I moved an import from test_*.py to conftest.py.

[blueyed]

Does using pytest -s make a difference?
(There is special wrapping of capturing around conftests IIRC, which might even be done unconditionally IIRC.)

[blueyed]

Also try it with the features branch of pytest - there might be fixes in this regard already.

[blueyed]

Maybe a flush is needed within pytest's capture machinery before moving fds around, or something similar?

[blueyed]

This appears to be a Python 2 bug/issue:

import sys
import tempfile
import time
import os


class Capture(object):
    def start(self):
        self._old_stdout = sys.stdout
        self._stdout_fd = self._old_stdout.fileno()
        self._saved_stdout_fd = os.dup(self._stdout_fd)
        self._file = sys.stdout = tempfile.TemporaryFile(mode='w+t')
        os.dup2(self._file.fileno(), self._stdout_fd)

    def stop(self):
        os.dup2(self._saved_stdout_fd, self._stdout_fd)
        os.close(self._saved_stdout_fd)
        sys.stdout = self._old_stdout
        self._file.seek(0)
        out = self._file.readlines()
        self._file.close()
        return out


if __name__ == "__main__":
    # Workaround: write anything (flushed) before capturing.
    # sys.stdout.write('a'); sys.stdout.flush()

    c = Capture()
    c.start()

    # XXX: py2: writing to orig stream causes redirected stream to be buffered?!
    sys.__stdout__.write("DBG_STDOUT...\n")
    # sys.__stdout__.flush()
    print("DBG_stdout")

    # py3: works as expected
    # ['DBG_STDOUT...\n', 'DBG_stdout\n']
    # sleep...
    # finished

    # py2: without flush:
    # sleep...
    # DBG_STDOUT...
    # ['DBG_stdout\n']
    # finished

    # py2: with flush (but takes 3s to show up):
    # sleep...
    # ['DBG_STDOUT...\n', 'DBG_stdout\n']
    # finished

    x = c.stop()
    print(x)
    sys.stderr.write("sleep...\n")
    time.sleep(3)
    print("finished")

(you can trigger it in pytest via sys.__stdout__.write("foo") already - no need for the C/C++ extension)

The example can be made to work in py2 by also assigning sys.__stdout__ (and doing so in pytest's SysCapture).
But that does not help for the output via the C++ program.

[blueyed]

Closing this off as an issue with Python 2 only (tested with 2.7.17, 3.7.4 - IIRC it also worked with Python 3.3).
Note that python -u and PYTHONUNBUFFERED=1 can be used as a workaround.

[blueyed]

However, my point is that if pytest is able to handle correctly the import dummy at the beginning of a test file, it should also be able to handle it correctly inside a conftest.py.

The issue here is that pytest captures (i.e. redirects) output during importing conftest modules, which then makes it behave differently from without output capturing (in py2).

[blueyed]

however I have see at least one real-world case in which things started to break and/or to function differently because I moved an import from test_*.py to conftest.py.

Maybe the behavior is different then, because something was printed already, and therefore the issue in py2 is not triggered then.

I recommend using py3 more.. :)

[blueyed]

Interesting fact from https://stackoverflow.com/a/29204619/15690:

And when you do the first output, in Python 2 it executes the isatty() system call once for the underlying file, and stores the result.
You should open an altogether new file and replace sys.stdout with it.

[blueyed]

Re-opening for now - #6062 appears to fix it.

[asottile]

hello, first off thank you for the issue!

python 2.x support has ended for pytest core.

we've decided in #7296 to close the python-2-specific issues to free up some space in our backlog. however, in accordance to our python 2.7 and 3.4 support community patches will still be accepted to the 4.6 series to fix bugs for python 2. (so if this issue is important to you and you have a patch to fix it, feel free to make a PR targeting the 4.6.x branch despite this ticket being closed).