Logging error when plugin is using old-style hook wrappers when pytest is not

[ConorMacBride]

Since #11123 switched from the old-style hook wrappers to the new-style hook wrappers, I'm getting an error in the pytest-mpl plugin tests when testing with pytest's main branch installed. If I upgrade pytest-mpl to use the new-style hook wrappers in its pytest_runtest_call, the error goes away. I thought I would log the issue here in case it will cause wider issues when pytest 8 is released.

I'm seeing this: https://github.com/matplotlib/pytest-mpl/actions/runs/7233619388/job/19709093922#step:10:4021

>                   warnings.warn(pytest.PytestUnraisableExceptionWarning(msg))
E                   pytest.PytestUnraisableExceptionWarning: Exception ignored in: <generator object LoggingPlugin.pytest_runtest_call at 0x7ff0fdef4ba0>
E                   
E                   Traceback (most recent call last):
E                     File "/home/runner/work/pytest-mpl/pytest-mpl/.tox/py312-test-mpldev-pytestdev/lib/python3.12/site-packages/_pytest/logging.py", line 813, in _runtest_for
E                       yield
E                   GeneratorExit
E                   
E                   During handling of the above exception, another exception occurred:
E                   
E                   Traceback (most recent call last):
E                     File "/home/runner/work/pytest-mpl/pytest-mpl/.tox/py312-test-mpldev-pytestdev/lib/python3.12/site-packages/_pytest/logging.py", line 830, in pytest_runtest_call
E                       yield from self._runtest_for(item, "call")
E                     File "/home/runner/work/pytest-mpl/pytest-mpl/.tox/py312-test-mpldev-pytestdev/lib/python3.12/site-packages/_pytest/logging.py", line 815, in _runtest_for
E                       log = report_handler.stream.getvalue().strip()
E                             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
E                   ValueError: I/O operation on closed file

I can't really find a minimal example as the failure appears in different tests between test runs and it usually only occurs when I run the full test suite. I thought it might be related to pytester but then I saw it occurring in some non-pytester tests.

To be clear, if I checkout b41acae in the tests they fail, but if I checkout the previous commit they pass. I'm not sure where to look to isolate the issue, but maybe someone who knows the pytest codebase better would.

I think I'll upgrade pytest-mpl to use the new-style hook wrappers. Would you recommend using the new style if pytest>=8 or if pluggy>=1.2? Thanks 🙂

$ pip freeze
contourpy==1.2.0
coverage==7.3.3
cycler==0.12.1
fonttools==4.46.0
iniconfig==2.0.0
Jinja2==3.1.2
kiwisolver==1.4.5
MarkupSafe==2.1.3
matplotlib==3.9.0.dev0
numpy==1.26.2
packaging==23.2
Pillow==10.1.0
pluggy==1.3.0
pyparsing==3.1.1
pytest @ git+https://github.com/pytest-dev/pytest.git@047ba83dabe492af938104fe0058597f67a672be
pytest-cov==4.1.0
pytest-mpl @ file:///home/runner/work/pytest-mpl/pytest-mpl/.tox/.tmp/package/1/pytest-mpl-0.16.2.dev112%2Bgf52143a.tar.gz#sha256=e8c5423fdcfede0d588a2e634c2dd9224203f45be766d6fce48632a7fde76732
python-dateutil @ git+https://github.com/dateutil/dateutil.git@0586f4afa26fc6799128d98d4f97a49c7d6ab314
six==1.16.0

[bluetech]

Thanks for trying pytest main and pinning down the commit. I am able to reproduce, I'll take a look in the next few days.

[bluetech]

Just from a quick look so I won't forget: it seems like the logging teardown is deferred until GC instead of being executed immediately; this causes it to happen after the pytest_unconfigure hook which had already closed the logging handler, then the "I/O operation on closed file" happens in the GC finalizer context (hence unraisable exception warning).

The issue therefore must lie in pluggy not close()ing the generators properly in some cases.

[bluetech]

Looked into it now. The problem is pytest-dev/pluggy#244, which was the focus of the latest pluggy releases. Unfortunately there was no way to fix it for old-style hookwrappers transparently (due to backward compat). So you must either change to new-style wrappers or use the new result.force_exception API, both of which require pluggy>=1.2.0.

If you're willing to require pluggy>=1.2.0, you can do something like this with old-style wrappers (whitespace ignored):

diff --git a/pytest_mpl/plugin.py b/pytest_mpl/plugin.py
index 625bf99..040652c 100644
--- a/pytest_mpl/plugin.py
+++ b/pytest_mpl/plugin.py
@@ -803,7 +803,8 @@ class ImageComparison:
 
             # Run test and get figure object
             wrap_figure_interceptor(self, item)
-            yield
+            result = yield
+            try:
                 if test_name not in self.return_value:
                     # Test function did not complete successfully
                     summary['status'] = 'failed'
@@ -864,6 +865,8 @@ class ImageComparison:
 
                 if summary['status'] == 'skipped':
                     pytest.skip(summary['status_msg'])
+            except BaseException as e:
+                result.force_exception(e)
 
     def generate_summary_json(self):
         json_file = self.results_dir / 'results.json'

or switch to new-style wrappers (just replace hookwrapper=True with wrapper=True).

If you can't require new pluggy, I guess you can "polyfill" result.force_exception(e) in the first approach like this (untested):

if hasattr(result, "force_exception"):  # pluggy>=1.2.0
    result.force_exception(e)
else:
    result._result = None
    result._excinfo = (type(e), e, e.__traceback__)

---

Technical details if you're interested:

The problem is: with old-style hookwrappers, you must not raise from the teardown. If the teardown raises, it causes the following teardowns to be skipped, and they are then collected by GC at some later point. This is what happens in pytest-mpl:

• pytest-mpl does some pytest.skip and pytest.fail in the teardown, which causes the logging plugin teardown to be skipped (deferred until gc)
• pytest logging plugin closes report_handler.stream in pytest_unconfigure
• At some later point, the deferred teardown runs in a GC finalizer, and also tries to report_handler.stream, which is already closed, so raises
• Because the exception is thrown in a GC finalizer, it does not propagate normally, it is an "unraisable exception". This is caught by the pytest unraisableexception plugin, which logs a warning
• pytest-mpl test suite fails on warnings, so the test suite fails

[ConorMacBride]

Thanks @bluetech, that's really helpful and it's interesting to learn more about the internals! We've now updated pytest-mpl to use either the force_exception method or the _excinfo attribute. Feel free to close this issue, unless you'd like it documented somewhere.