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?