Improve error message when tests use closed stdout/stderr (capture)

@nicoddemus

This is still an issue with the latest pytest across tests (e.g. when one tests change the logging config and add a stream handler pointing to stdout, a subsequent test that doesn't setup logging and tries to write to logging will fail).

I think the issue boils down to the fact that if you set up a Stream Handler and you enable capsys the actual output stream will be a pytest stream that will be closed and thrown away at the next test in the test suite. So when a subsequent test tries to write to it you get this error. Adding the following fixture fixed this:

LOGGER = logging.getLogger()

@pytest.fixture(autouse=True)
def ensure_logging_framework_not_altered():
    before_handlers = list(LOGGER.handlers)
    yield
    LOGGER.handlers = before_handlers

Should this be automatically done always by pytest? Granted for this to work ideally you would need to do it for all loggers, not just the root one. In this case, for me, this was enough as I was only set up a custom stream logger onto the root logger.

In an ideal world, I would expect though pytest to cleanup loggig configurations at the end tests that requested the caplog fixture.

Originally posted by @gaborbernat in #14 (comment)

@gaborbernat

Thanks @gaborbernat for the detailed description.

Indeed seems like pytest should automatically cleanup the handlers somehow, not sure how to do it though ensuring we don't break existing things...

cc @Thisch

I don't think pytest should automatically clean up any of a user's resources as it's arguably a correctness problem with the test suite or user code

It not cleanup we should alter the capsys stream to raise a more meaningful error on write than stream closed and maybe point out the test where that capsys was pulled from?

yeah I'm fine with a better error message -- somehow notify the user that they're reassigning globals to sys.std* streams as a test side-effect

I don't think pytest should automatically clean up any of a user's resources as it's arguably a correctness problem with the test suite or user code
yeah I'm fine with a better error message -- somehow notify the user that they're reassigning globals to sys.std* streams as a test side-effect

Oh right, I agree. Initially I thought we were not cleaning our handlers correctly, but I misunderstood the issue.

yeah I'm fine with a better error message -- somehow notify the user that they're reassigning globals to sys.std* streams as a test side-effect

Actually IIUC the tests are not reassigning sys.std*, but they are installing handlers that point to sys.stdout (which is a buffer installed by pytest) and not cleaning up the handlers afterwards, making the next test fail when its logging operations try to write to the now-closed-buffer.

Needs more investigation, but if the message originates from here:

pytest/src/_pytest/capture.py

Lines 420 to 427 in 2d613a0

    
           def write(self, obj): 
        
               if isinstance(obj, str): 
        
                   obj = obj.encode(self.encoding, "replace") 
        
               else: 
        
                   raise TypeError( 
        
                       "write() argument must be str, not {}".format(type(obj).__name__) 
        
                   ) 
        
               self.buffer.write(obj)

We just need to raise a more meaningful message if the buffer is already closed at this point.

yeah I didn't say they're modifying the sys.std* references, I was very careful to say "assigning globals to sys.std* streams" ;) -- logging is all sneaky global variables after all

ok at work and will report back

@betchern0t

@betchern0t
Note that the above could also "just work" (instead of improving the crash/error message). See #6034 for something you might want to pick up for this.

@blueyed

@blueyed while your proposed solution is undoubtedly superior, I was looking for a simple task to get me started. I have lots of dev/it experience but not so much python and no experience with this codebase. I am quite happy for someone else to supersede my work when they are able.

I have found a suitable place to intervene and am just about to look at how to get the test name, test file name and line number to place in the error message.

imo making it "just work" is not the correct solution here -- the code which triggers this has a bug (it leaks global state as a side-effect of the test). improving the error message is (imo) the only solution here

I have now looked at this issue and #14 and #5502. It seems to me that - as has been said elsewhere - the issue is between pytest hyjacking std* and adding a stream buffer and other things assuming that std* are standard file descriptors. As such there are actually a number of places where we could possibly catch the exception and write an indicative error message. But this works most of the time so I need a valid test case to indicate which path through code it is.

My thanks to Asottile but that test case runs perfectly for me. I tried some of the other test cases in the other two issues but the only one I can make to work/fail is:

import atexit
import logging

LOGGER = logging.getLogger(__name__)

def test_1():
    pass    

atexit.register(lambda: LOGGER.error("test in atexit"))
logging.basicConfig()`

Looking at this I am not sure this is a relevant test. My understanding of this code is that it attempts to log something at a very late stage of process tear down which I would expect to produce these kind of errors, What is more there is nothing to say beyond what is produced. There isn't a specific test to point to.

As such there are actually a number of places where we could possibly catch the exception and write an indicative error message. But this works most of the time so I need a valid test case to indicate which path through code it is.

IIUC we don't need to actually catch the exception anywhere, we just need to raise a better error message during write:

pytest/src/_pytest/capture.py

Lines 420 to 427 in 622995a

    
           def write(self, obj): 
        
               if isinstance(obj, str): 
        
                   obj = obj.encode(self.encoding, "replace") 
        
               else: 
        
                   raise TypeError( 
        
                       "write() argument must be str, not {}".format(type(obj).__name__) 
        
                   ) 
        
               self.buffer.write(obj)

Instead of:

self.buffer.write(obj)

Something like:

try:
    self.buffer.write(obj)
except (IOError, ValueError) as e:
    raise type(e)("Error from stream created by test {nodeid}".format(self.test_nodeid))

So the error message will help the user finding out about the test.

Thankyou Nicoddemus. The issue is that my analysis has found several places where this error can occur under different circumstances. I would have to go back and look to see exactly the places I found but at least two in the capture file. I had pretty much what you suggest in the first place before looking at the second. The issue is that there isn't a hard fault and so I could end up patching this in many locations and still not fix the issue.

The issue is that my analysis has found several places where this error can occur under different circumstances.

You mean several places in capture.py, or over pytest?

I would focus only on the place reported by the issue because it is the situation where logging will fail.

Nicoddemus I mean several points in capture.py. There is nothing definitive to point to the bug in the issue. Yes I could put a try except block in write - what I call catching the exception - but my testing suggested other locations.

In case this helps as another example, I can't run pytest on Windows 10 with PyWinAuto without seeing the Fatal exception/ValueError

Minimum example:

import logging
import pytest
from pywinauto.application import Application

def test_case():
    assert True

Output:

(py375) C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error>pytest
=========================================== test session starts =========================================== 
platform win32 -- Python 3.7.5, pytest-5.3.4, py-1.8.1, pluggy-0.13.1
rootdir: C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error
plugins: dash-1.8.0, cov-2.8.1, html-2.0.1, metadata-1.8.0, timeout-1.3.4
collected 1 item                                                                                            

tests\test_pywinauto_fatalerror.py .                                                                 [100%] 

============================================ 1 passed in 0.35s ============================================ 
Windows fatal exception: code 0x80010108

Thread 0x00006494 (most recent call first):
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\comtypes\__init__.py", line 185 in shutdown
Windows fatal exception: code 0x80010108

Thread 0x00006494 (most recent call first):
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\comtypes\__init__.py", line 185 in shutdown

(py375) C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error>poetry update

requirements.txt

atomicwrites==1.3.0; sys_platform == "win32"
attrs==19.3.0
colorama==0.4.3; sys_platform == "win32"
comtypes==1.1.7
importlib-metadata==1.4.0; python_version < "3.8"
more-itertools==8.1.0
packaging==20.0
pluggy==0.13.1
py==1.8.1
pyparsing==2.4.6
pytest==5.3.4
pywin32==227
pywinauto==0.6.8
six==1.14.0
wcwidth==0.1.8
zipp==2.0.0; python_version < "3.8"

The below log output is from the extended script shown here: pywinauto/pywinauto#858 (comment)

(py375) C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error>pytest
=========================================== test session starts =========================================== 
platform win32 -- Python 3.7.5, pytest-5.3.4, py-1.8.1, pluggy-0.13.1
rootdir: C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error
plugins: dash-1.8.0, cov-2.8.1, html-2.0.1, metadata-1.8.0, timeout-1.3.4
collected 1 item                                                                                            

tests\test_pywinauto_fatalerror.py .                                                                 [100%] 

============================================ 1 passed in 0.36s ============================================ 
--- Logging error ---
Traceback (most recent call last):
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\logging\__init__.py", line 1028, in emit
    stream.write(msg + self.terminator)
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\_pytest\capture.py", line 427, in write
    self.buffer.write(obj)
ValueError: I/O operation on closed file
Call stack:
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\comtypes\__init__.py", line 183, in shutdown
    _debug("Calling CoUnititialize()")
Message: 'Calling CoUnititialize()'
Arguments: ()
Windows fatal exception: code 0x80010108

Thread 0x00004530 (most recent call first):
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\comtypes\__init__.py", line 185 in shutdown
Windows fatal exception: code 0x80010108

Thread 0x00004530 (most recent call first):
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\comtypes\__init__.py", line 185 in shutdown
--- Logging error ---
Traceback (most recent call last):
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\logging\__init__.py", line 1028, in emit
    stream.write(msg + self.terminator)
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\_pytest\capture.py", line 427, in write
    self.buffer.write(obj)
ValueError: I/O operation on closed file
Call stack:
  File "c:\users\king.kyle\appdata\local\continuum\anaconda2\envs\py375\lib\site-packages\comtypes\__init__.py", line 193, in shutdown
    _debug("CoUnititialize() done.")
Message: 'CoUnititialize() done.'
Arguments: ()

(py375) C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error>

Windows Error Message:

@KyleKing

Thanks @KyleKing, can you please confirm that passing -s doesn't cause the error?

Thanks, the fatal error still occurs with the -s or --capture=no flags so likely not be within the scope for this issue

I think the root cause is due to changes in Ole32.dll for Windows 10

I'm having trouble replicating the Fatal Exception from comtypes without running pytest. I've experimented with calling the method in a thread, but the script doesn't report an error.

I created an example test case that uses a snippet from pywinauto, but doesn't require the full package to be imported:

import comtypes
import comtypes.client

def test_case():
    comtypes.client.GetModule('UIAutomationCore.dll')
    ui_automation_client = comtypes.gen.UIAutomationClient
    iuia = comtypes.CoCreateInstance(
        ui_automation_client.CUIAutomation().IPersist_GetClassID(),
        interface=ui_automation_client.IUIAutomation,
        clsctx=comtypes.CLSCTX_INPROC_SERVER,
    )
    iuia.GetRootElement()
    assert True

~~Do you know why pytest is calling shutdown() from comtypes?~~
Edit: shutdown() is called on exit (using import atexit; atexit.register(shutdown); del shutdown in comtypes)

~~Edit: Also, doesn't occur when using Python installed from Python.org. occurs with Python installed by Anaconda~~
Edit: Issue only occurs in Python 3.7 and above regardless of the virtual environment or how Python was installed (Py3.7.X + comtypes + pytest)

What is pytest doing that is leading to the Fatal Exception?
Edit: Any advice on next steps?

(I've tried modifying the related package source code, but debugging this issue is tricky with such an unhelpful traceback/error. Should I create a new issue?)

(base) C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error>poetry run pytest -s
=========================================== test session starts =========================================== 
platform win32 -- Python 3.6.7, pytest-5.3.4, py-1.8.1, pluggy-0.13.1
rootdir: C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error
collected 1 item                                                                                            

tests\test_pywinauto_fatalerror.py test_case process: 1376
.

============================================ 1 passed in 0.22s ============================================ 
Windows fatal exception: code 0x80010108

Thread 0x000044fc (most recent call first):
  File "c:\users\king.kyle\appdata\local\pypoetry\cache\virtualenvs\pywinauto-fatalerror-8tfupx_2-py3.6\lib\site-packages\comtypes\__init__.py", line 185 in shutdown
Windows fatal exception: code 0x80010108

Thread 0x000044fc (most recent call first):
  File "c:\users\king.kyle\appdata\local\pypoetry\cache\virtualenvs\pywinauto-fatalerror-8tfupx_2-py3.6\lib\site-packages\comtypes\__init__.py", line 185 in shutdown

(base) C:\Users\king.kyle\Developer\Packages\PyWinAuto-Win10Error>

Edited 23Jan2020 and 24Jan2020

Update 24Jan2020: I don't know why this fatal error was occurring, but I disabled the pop-ups, which allows me to run through my pywinauto test suite and carry on 😄

@asottile

I don't think pytest should automatically clean up any of a user's resources as it's arguably a correctness problem with the test suite or user code

@asottile The fixture works only when logging is set at function-level, when i define logging at module level, still tests fail with error
#5577

Reset logging handlers after logging tests.

Navigation Menu

Repository navigation

Improve error message when tests use closed stdout/stderr (capture) #5743

7 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	def write(self, obj):
	if isinstance(obj, str):
	obj = obj.encode(self.encoding, "replace")
	else:
	raise TypeError(
	"write() argument must be str, not {}".format(type(obj).__name__)
	)
	self.buffer.write(obj)

Improve error message when tests use closed stdout/stderr (capture) #5743

Description

Activity

nicoddemus commented on Aug 15, 2019

asottile commented on Aug 15, 2019

gaborbernat commented on Aug 15, 2019

asottile commented on Aug 15, 2019

nicoddemus commented on Aug 15, 2019

nicoddemus commented on Aug 15, 2019

nicoddemus commented on Aug 15, 2019

asottile commented on Aug 15, 2019

7 remaining items

betchern0t commented on Dec 23, 2019

blueyed commented on Dec 23, 2019

betchern0t commented on Dec 25, 2019

asottile commented on Dec 25, 2019

betchern0t commented on Dec 29, 2019

nicoddemus commented on Jan 10, 2020

betchern0t commented on Jan 11, 2020

nicoddemus commented on Jan 11, 2020

betchern0t commented on Jan 11, 2020

KyleKing commented on Jan 22, 2020

nicoddemus commented on Jan 22, 2020

KyleKing commented on Jan 23, 2020

KyleKing commented on Jan 23, 2020

karthikvadla commented on Mar 17, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions