pytest icon indicating copy to clipboard operation
pytest copied to clipboard

Published 20 hours ago • verified publisher icon pytest-dev

Ensure stdin and stdout are in blocking mode before writing test summary

Open godfryd opened this issue 8 years ago • 23 comments

Hello,

I'm running unit tests in parallel with such configuration: platform linux2 -- Python 2.7.12, pytest-3.0.6, py-1.4.31, pluggy-0.4.0 -- /tmp/pyve/bin/python2 plugins: timeout-1.2.0, xdist-1.15.0, cov-2.4.0

And I'm getting quite often such exception as follows. As this is temporary problem with writing output maybe there could be added a loop that catches this exception and tries again at least several times?

Traceback (most recent call last):
File "/tmp/pyve/bin/py.test", line 11, in <module>
sys.exit(main())
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/config.py", line 57, in main
return config.hook.pytest_cmdline_main(config=config)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
return self._inner_hookexec(hook, methods, kwargs)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
_MultiCall(methods, kwargs, hook.spec_opts).execute()
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 614, in execute
res = hook_impl.function(*args)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/main.py", line 127, in pytest_cmdline_main
return wrap_session(config, _main)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/main.py", line 122, in wrap_session
exitstatus=session.exitstatus)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 745, in __call__
return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 339, in _hookexec
return self._inner_hookexec(hook, methods, kwargs)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 334, in <lambda>
_MultiCall(methods, kwargs, hook.spec_opts).execute()
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 613, in execute
return _wrapped_call(hook_impl.function(*args), self.execute)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/vendored_packages/pluggy.py", line 250, in _wrapped_call
wrap_controller.send(call_outcome)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/terminal.py", line 367, in pytest_sessionfinish
self.summary_failures()
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/terminal.py", line 484, in summary_failures
self._outrep_summary(rep)
File "/tmp/pyve/local/lib/python2.7/site-packages/_pytest/terminal.py", line 513, in _outrep_summary
self._tw.line(content)
File "/usr/lib/python2.7/dist-packages/py/_io/terminalwriter.py", line 201, in line
self.write(s, **kw)
File "/usr/lib/python2.7/dist-packages/py/_io/terminalwriter.py", line 198, in write
write_out(self._file, markupmsg)
File "/usr/lib/python2.7/dist-packages/py/_io/terminalwriter.py", line 333, in write_out
fil.write(msg)
IOError: [Errno 11] Resource temporarily unavailable
make: *** [tests] Error 1
make: write error: stdout

godfryd avatar Feb 15 '17 09:02 godfryd

without more context on how/what you run we will have to assume you created this problem yourself

RonnyPfannschmidt avatar Feb 15 '17 09:02 RonnyPfannschmidt

The error is being raised when writing to the terminal, although you're running py-1.4.31. Perhaps try to update to py-1.4.32?

@godfryd without more information it is hard to pin-point the problem.

nicoddemus avatar Feb 15 '17 10:02 nicoddemus

I run the tests in parallel, there are 6 processes. What else I can provide? What do you need? I cannot show you how to reproduce it - this is an internal, closed project.

How do you see adding there a loop with try/except for that kind of error?

Now, I'm trying py-1.4.32. Thanks for the tip.

godfryd avatar Feb 15 '17 12:02 godfryd

Does your project do anything related to the terminal, stdout or stderr at all? Is it running locally only or remotely?

I cannot show you how to reproduce it - this is an internal, closed project.

Perhaps you can isolate the problem in a reproducible example?

How do you see adding there a loop with try/except for that kind of error?

I'm afraid adding such a try/except to py without knowing the underlying cause would be irresponsible as this can potentially hide errors which are not really related to pytest/pytest-xdist.

Having said that you can fork py and add that loop yourself to at least try to find the root cause of the problem.

nicoddemus avatar Feb 15 '17 12:02 nicoddemus

Updating py to version 1.4.32 didn't help. Do you have any other tips how to debug it?

godfryd avatar Feb 24 '17 12:02 godfryd

  1. Does your project do anything related to the terminal, stdout or stderr at all?

  2. Is it running locally only or remotely?

  3. Does this happen if you run without pytest-xdist?

  4. It is clear that something is making in your environment is making stdout unavailable:

 [Errno 11] Resource temporarily unavailable

One idea is to monkeypatch sys.stdout.close at the very beginning of your tests with a mock function that fails when called. This way you will get a traceback if someone is closing it behind your back. This must be done before pytest capture even begins, perhaps even before main to be sure:

import pytest
import sys

def boom_it(): assert 0
sys.stdout.close = boom_it
pytest.main()

Then execute that script instead of pytest directly.

Other than that, without looking at some code is hard to suggest what that the problem might be. ☹️

nicoddemus avatar Feb 24 '17 23:02 nicoddemus

(Just realized 4 probably won't find your problem, because you would probably get an I/O operation on closed file instead of Resource temporarily unavailable if someone is closing stdout).

nicoddemus avatar Feb 24 '17 23:02 nicoddemus

Closing from lack of response.

nicoddemus avatar Sep 28 '17 21:09 nicoddemus

We are constantly running into this fault. It seems like the capture functionality of pytest causes this.

Basically the problem disappears when capturing of test output is disabled. However, this make the test logs unreadable due to the bulk of non-error output.

I'll try to reproduce.

tlandschoff-scale avatar Apr 23 '19 12:04 tlandschoff-scale

@tlandschoff-scale Thanks for the info. Do you see the same traceback? Can you post yours anyway for reference (updated location), please? A minimal test case would be good indeed. Is xdist / parallelism involved in your case?

blueyed avatar Apr 23 '19 15:04 blueyed

Unfortunately we are still at an ancient pytest version and I am still unable to reproduce this problem.

Most of the time this was triggered in a plugin I wrote to report left over threads. I tried to dive down into the cause there but adding debugging code (catching the error and retrying) caused the problem to disappear as it seems.

With pytest 3.7.4 we get this traceback:

  File "/opt/scalesdk/python27/lib/python2.7/runpy.py", line 174, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/opt/scalesdk/python27/lib/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pytest.py", line 68, in <module>
    raise SystemExit(pytest.main())
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/_pytest/config/__init__.py", line 65, in main
    return config.hook.pytest_cmdline_main(config=config)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/callers.py", line 81, in get_result
    _reraise(*ex)  # noqa
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/_pytest/main.py", line 208, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/_pytest/main.py", line 201, in wrap_session
    session=session, exitstatus=session.exitstatus
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/_pytest/terminal.py", line 582, in pytest_sessionfinish
    outcome = yield
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/callers.py", line 208, in _multicall
    return outcome.get_result()
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/callers.py", line 81, in get_result
    _reraise(*ex)  # noqa
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/pluggy/callers.py", line 182, in _multicall
    next(gen)  # first yield
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/_pytest/terminal.py", line 604, in pytest_terminal_summary
    self.summary_failures()
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/_pytest/terminal.py", line 735, in summary_failures
    self._outrep_summary(rep)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/_pytest/terminal.py", line 769, in _outrep_summary
    self._tw.line(content)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/py/_io/terminalwriter.py", line 234, in line
    self.write(s, **kw)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/py/_io/terminalwriter.py", line 224, in write
    write_out(self._file, markupmsg)
  File "/builds/loco-dev/loco/venv/lib/python2.7/site-packages/py/_io/terminalwriter.py", line 369, in write_out
    fil.write(msg)
IOError: [Errno 11] Resource temporarily unavailable

It seems to suffice that a test case creates a lot of output on stdout. But running just this (failing) test does not reproduce the IOError. I assume that some SIGCHLD handler is involved, but was not able to pinpoint this.

tlandschoff-scale avatar May 14 '19 17:05 tlandschoff-scale

Is xdist / parallelism involved in your case?

No, apart from some tests starting child processes and using threads, but nothing driven from pytest.

tlandschoff-scale avatar May 14 '19 17:05 tlandschoff-scale

I have no idea how this fails for us at random intervals. I just created a test case that forks hundreds of threads, writes thousands of lines to stdout and then fails, having all the processes terminate starting at that instant.

Works fine, not causing the "resource temporarily unavailable".

Frankly I have no idea what could cause this on stdout.

tlandschoff-scale avatar May 14 '19 18:05 tlandschoff-scale

@tlandschoff-scale

Unfortunately we are still at an ancient pytest version

I'd only investigate further after updating that - it might be fixed already, and you are wasting time there then that is better spent upgrading.

blueyed avatar May 14 '19 20:05 blueyed

Thing is that fil.write refers to stdout and returns EAGAIN, which can never happen as far as I know.

The problem manifests itself only in our GitLab CI, never on a local machine. About every 3rd test run fails because of that.

What I want to say: I don't think that upgrading pytest will change anything here as writing a blocking stdout should not return EAGAIN.

tlandschoff-scale avatar May 15 '19 07:05 tlandschoff-scale

fil.write refers to stdout and returns EAGAIN, which can never happen as far as I know.

Seems to be possible: https://github.com/ParallelSSH/parallel-ssh/issues/165#issuecomment-477510374 https://trac.edgewall.org/ticket/2066

It depends probably on if stdout is set or blocking or not, which might be something that GitLab is doing.

Maybe pytest's capturing could ensure that it is not blocking?

blueyed avatar May 15 '19 09:05 blueyed

I added reporting of the O_NONBLOCK flag on sys.stdout to our tests. It is unset at test setup and also at teardown. I wonder if it is set temporarily by some test or plugin. Unfortunately it seems impossible to shield this "global variable" against modification.

My next attempt will be to monitor the flag in an extra thread and report any change.

tlandschoff-scale avatar May 15 '19 09:05 tlandschoff-scale

Re-opening for now. Just came across this, which might be relevant: https://github.com/zh-explorer/pwndemo/blob/17215e3f8340f374553ad8c79aa85da6f0bb0357/pwnlib/tubes/process.py#L281-L287

blueyed avatar May 15 '19 11:05 blueyed

Also this: https://github.com/pytest-dev/pytest/issues/1886#issuecomment-274033622 (Python's buffering options).

blueyed avatar May 15 '19 11:05 blueyed

I finally found the cause in our test suite: We are using TypeScript for some scripting and npm to build the javascript code (basically ensure that the compiled code is up to date).

Now node seems to set stdout and stderr to non-blocking as reported in https://github.com/nodejs/node/issues/14752. Seems like I failed to properly diagnose the flag at shutdown, I think the test output on the CI was truncated.

The fun thing: node manipulate the blocking flag only when the output goes to a pipe as it seems:

(python27)torsten.landschoff@horatio:~$ node -e 42 && python -c "import os,fcntl; print([fcntl.fcntl(n, fcntl.F_GETFL) & os.O_NONBLOCK for n in (1, 2)])"
[0, 0]
(python27)torsten.landschoff@horatio:~$ (node -e 42 && python -c "import os,fcntl; print([fcntl.fcntl(n, fcntl.F_GETFL) & os.O_NONBLOCK for n in (1, 2)])")|cat
[2048, 0]
(python27)torsten.landschoff@horatio:~$ (node -e 42 && python -c "import os,fcntl; print([fcntl.fcntl(n, fcntl.F_GETFL) & os.O_NONBLOCK for n in (1, 2)])") 2>&1 |cat
[2048, 2048]

I would be really happy for pytest to assert that stdout and stderr are blocking when started and before printing the test summary! (Would have saved quite some headache).

Surely not a fault of pytest though. Setting stdout and stderr as non-blocking in a program (without even resetting it) is highly questionable to say the least.

tlandschoff-scale avatar May 15 '19 17:05 tlandschoff-scale

Is this responsible for getting random INFO lines after the pytest summary when using logging.basicConfig(level=logging.INFO); pytest.main(['--log-cli-level', 'warning']) and python instead of python -u? Testcase:

import logging, os, pytest, sys
os.environ['PYTHONUNBUFFERED'] = '1'  # Doesn't help on Windows 10.


def test_buffered_filter_fail():
	for i in range(1000):
		logging.info("i = %i", i)


if __name__ == '__main__':
	logging.basicConfig(level=logging.INFO)
	pytest.main(['--log-cli-level', 'warning', *sys.argv])

(.venv) PS C:\Users\C\Documents\code\GitHub\steganography> python .\test\test_pytest.py -v -k test_buffered
======================================================== test session starts ========================================================
platform win32 -- Python 3.8.5, pytest-7.1.2, pluggy-0.13.1 -- C:\Users\C\Documents\code\GitHub\steganography\.venv\Scripts\python.execachedir: .pytest_cache
rootdir: C:\Users\C\Documents\code\GitHub\steganography
plugins: pylama-8.4.1
collected 1 item                                                                                                                      

test/test_pytest.py::test_buffered_filter_fail PASSED                                                                          [100%]

========================================================= 1 passed in 0.86s ========================================================= 
INFO:root:i = 0
[...]
INFO:root:i = 435
(.venv) PS C:\Users\C\Documents\code\GitHub\steganography> python -u .\test\test_pytest.py -v -k test_buffered
======================================================== test session starts ========================================================
platform win32 -- Python 3.8.5, pytest-7.1.2, pluggy-0.13.1 -- C:\Users\C\Documents\code\GitHub\steganography\.venv\Scripts\python.execachedir: .pytest_cache
rootdir: C:\Users\C\Documents\code\GitHub\steganography
plugins: pylama-8.4.1
collected 1 item                                                                                                                      

test/test_pytest.py::test_buffered_filter_fail PASSED                                                                          [100%]

========================================================= 1 passed in 0.90s ========================================================= 
(.venv) PS C:\Users\C\Documents\code\GitHub\steganography>

CTimmerman avatar Aug 15 '22 00:08 CTimmerman

Is this responsible for getting random INFO lines after the pytest summary when using logging.basicConfig(level=logging.INFO); pytest.main(['--log-cli-level', 'warning']) and python instead of python -u? Testcase:

No. This was about stdout/stderr being non-blocking. That results in errors on write operations but will not change the order.

import logging, os, pytest, sys
os.environ['PYTHONUNBUFFERED'] = '1'  # Doesn't help on Windows 10.

This shouldn't help on any system, as PYTHONUNBUFFERED is read on interpreter bootstrapping. Python code executes after bootstrapping, so the bootstrapping code will not see the new value. If this actually makes a difference, I'd be very curious. :smile:

The problem in your code snippet is calling of logging.basicConfig, which adds an extra logger which writes to stderr. On Linux it appears to make no difference as it seems to be captured with the usual stdout and stderr output.

You can make this visible on Linux by failing the test (adding e.g. assert False in the last line), which will show you the output twice:

$ python3 -u test_foo.py -v
[...]
E       assert False

test_foo.py:8: AssertionError
---------------------------------------------- Captured stderr call ----------------------------------------------
INFO:root:i = 0
INFO:root:i = 1
INFO:root:i = 2
[...]
----------------------------------------------- Captured log call ------------------------------------------------
test_foo.py                  7 INFO     i = 0
test_foo.py                  7 INFO     i = 1
test_foo.py                  7 INFO     i = 2
[...]

Greetings, Torsten

tlandschoff-scale avatar Aug 15 '22 08:08 tlandschoff-scale

Thanks, but why does the problem not appear on Windows when using python -u, showing only the "Captured log call" on assert fail? With just python Windows also show it again after "1 failed in 1.52s" ending again with INFO:root:i = 435, even in Git Bash. The logger appears to fail:

[...]
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1084, in emit
    stream.write(msg + self.terminator)
OSError: [WinError 6] The handle is invalid
Call stack:
  File "test_pytest.py", line 15, in <module>
    pytest.main(['--log-cli-level', 'warning', *sys.argv])
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\config\__init__.py", line 164, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 315, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 268, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 322, in _main
    config.hook.pytest_runtestloop(session=session)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 347, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 111, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 130, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 219, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 258, in call_runtest_hook
    return CallInfo.from_call(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 338, in from_call
    result: Optional[TResult] = func()
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 259, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 166, in pytest_runtest_call
    item.runtest()
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\python.py", line 1761, in runtest
    self.ihook.pytest_pyfunc_call(pyfuncitem=self)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\python.py", line 192, in pytest_pyfunc_call
    result = testfunction(**testargs)
  File "C:\Users\C\Documents\code\GitHub\steganography\test\test_pytest.py", line 9, in test_buffered_filter_fail
    logging.info("i = %i", i)
Message: 'i = %i'
Arguments: (999,)

Less so with -u:

C:\Users\C\Documents\code\GitHub\steganography\test>python -u test_pytest.py
============================================================================================================================ test session starts =============================================================================================================================
platform win32 -- Python 3.8.5, pytest-7.1.2, pluggy-0.13.1
rootdir: C:\Users\C\Documents\code\GitHub\steganography\test
plugins: pylama-7.7.1, timeout-1.4.2
collected 1 item

test_pytest.py::test_buffered_filter_fail FAILED                                                                                                                                                                                                                        [100%]

================================================================================================================================== FAILURES ==================================================================================================================================
_________________________________________________________________________________________________________________________ test_buffered_filter_fail __________________________________________________________________________________________________________________________

    def test_buffered_filter_fail():
        for i in range(1000):
                logging.info("i = %i", i)
>       assert False
E    assert False

test_pytest.py:10: AssertionError
---------------------------------------------------------------------------------------------------------------------------- Captured stderr call ----------------------------------------------------------------------------------------------------------------------------
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1084, in emit
    stream.write(msg + self.terminator)
OSError: [WinError 6] The handle is invalid
Call stack:
  File "test_pytest.py", line 15, in <module>
    pytest.main(['--log-cli-level', 'warning', *sys.argv])
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\config\__init__.py", line 164, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 315, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 268, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 322, in _main
    config.hook.pytest_runtestloop(session=session)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 347, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 111, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 130, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 219, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 258, in call_runtest_hook
    return CallInfo.from_call(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 338, in from_call
    result: Optional[TResult] = func()
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 259, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 166, in pytest_runtest_call
    item.runtest()
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\python.py", line 1761, in runtest
    self.ihook.pytest_pyfunc_call(pyfuncitem=self)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\python.py", line 192, in pytest_pyfunc_call
    result = testfunction(**testargs)
  File "C:\Users\C\Documents\code\GitHub\steganography\test\test_pytest.py", line 9, in test_buffered_filter_fail
    logging.info("i = %i", i)
Message: 'i = %i'
Arguments: (0,)
--- Logging error ---
Traceback (most recent call last):
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\logging\__init__.py", line 1084, in emit
    stream.write(msg + self.terminator)
OSError: [WinError 6] The handle is invalid
Call stack:
  File "test_pytest.py", line 15, in <module>
    pytest.main(['--log-cli-level', 'warning', *sys.argv])
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\config\__init__.py", line 164, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 315, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 268, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 322, in _main
    config.hook.pytest_runtestloop(session=session)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\main.py", line 347, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 111, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 130, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 219, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 258, in call_runtest_hook
    return CallInfo.from_call(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 338, in from_call
    result: Optional[TResult] = func()
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 259, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\runner.py", line 166, in pytest_runtest_call
    item.runtest()
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\_pytest\python.py", line 1761, in runtest
    self.ihook.pytest_pyfunc_call(pyfuncitem=self)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 93, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\manager.py", line 84, in <lambda>
    self._inner_hookexec = lambda hook, methods, kwargs: hook.multicall(
  File "C:\Users\C\AppData\Local\Programs\Python\Python38\lib\site-packages\pluggy\callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "C:\Users\C\AppData\Local\Programs\Python
----------------------------------------------------------------------------------------------------------------------------- Captured log call ------------------------------------------------------------------------------------------------------------------------------
INFO     root:test_pytest.py:9 i = 0
[...]
INFO     root:test_pytest.py:9 i = 999
========================================================================================================================== short test summary info ===========================================================================================================================
FAILED test_pytest.py::test_buffered_filter_fail - assert False
============================================================================================================================= 1 failed in 1.47s ==============================================================================================================================

C:\Users\C\Documents\code\GitHub\steganography\test>

Even with the extra logger that doesn't appear in loggerDict, pytest on python -u eats the test log output of

if __name__ == "__main__":
	# Don't create own logger as that's strongly advised against (So why offer it?!) according to https://docs.python.org/3/howto/logging.html
	# Use global setting and disable loggers of other modules instead. Also looks dirty!

	logging.basicConfig(level=logging.INFO)  # Conflicts with pytest. https://github.com/pytest-dev/pytest/issues/2251#issuecomment-1214488264

	# Hide PIL lines.
	loggers = [logging.getLogger(name) for name in logging.root.manager.loggerDict]  # pylint: disable=no-member
	for v in loggers:
		print("Existing logger", v)
		v.setLevel('WARNING')

	# test_fuzz()
	logging.warning('------------------BEFORE--------------------')

	pytest.main(['--log-cli-level', 'error', *sys.argv])

	logging.warning('------------------AFTER--------------------')

(.venv) 
C@MSI MINGW64 ~/Documents/code/GitHub/steganography (main)
$ python -u test/test_steganography.py -v -k test_fuzz --log-cli-level=error
Existing logger <Logger PIL.Image (INFO)>
Existing logger <Logger PIL (INFO)>
WARNING:root:------------------BEFORE--------------------
====================================================== test session starts ======================================================
platform win32 -- Python 3.8.5, pytest-7.1.2, pluggy-0.13.1 -- C:\Users\C\Documents\code\GitHub\steganography\.venv\Scripts\python.exe
cachedir: .pytest_cache
rootdir: C:\Users\C\Documents\code\GitHub\steganography
plugins: pylama-8.4.1
collected 3 items / 2 deselected / 1 selected

test/test_steganography.py::test_fuzz PASSED                                                                               [100%]

================================================ 1 passed, 2 deselected in 3.38s ================================================ 
WARNING:root:------------------AFTER--------------------
(.venv) 
C@MSI MINGW64 ~/Documents/code/GitHub/steganography (main)
$

CTimmerman avatar Aug 15 '22 11:08 CTimmerman