Opened 4 days ago

Closed 3 days ago

Last modified 7 hours ago

#36056 closed Cleanup/optimization (fixed)

Fix ignored exceptions in OutputWrapper.flush()

Reported by: Adam Johnson Owned by: Adam Johnson
Component: Core (Management commands) Version: dev
Severity: Normal Keywords:
Cc: Triage Stage: Ready for checkin
Has patch: yes Needs documentation: no
Needs tests: no Patch needs improvement: no
Easy pickings: no UI/UX: no

Description

Running pytest on two different projects with Python 3.13, I’ve seen this error logged after tests pass:

$ pytest
...
==== 1 passed in 0.01s ====
Exception ignored in: <django.core.management.base.OutputWrapper object at 0x173326230>
Traceback (most recent call last):
  File "/.../.venv/lib/python3.13/site-packages/django/core/management/base.py", line 171, in flush
    self._out.flush()
ValueError: I/O operation on closed file.
...

It can appear multiple times, depending on how many management commands are tested.

This message is from Python’s unraisable exception hook, logging the minimal available information for an exception raised during a destructor or garbage collection.

I minimized the test case to find that it requires a test that captures the exception from a failing management command, minimized to:

import pytest
from django.core.management import call_command
from django.core.management.base import CommandError
from django.test import SimpleTestCase


class ExampleTests(SimpleTestCase):
    def test_it(self):
        with pytest.raises(CommandError) as excinfo:
            call_command("check", "--non")

This test runs the check management command with a non-existent option, triggering an error.
It can be run with pytest and pytest-django installed like:

$ pytest --ds=test_example test_example.py
========================= test session starts =========================
platform darwin -- Python 3.13.1, pytest-8.3.4, pluggy-1.5.0
django: version: 5.1.4, settings: test_example (from option)
rootdir: /.../example
configfile: pyproject.toml
plugins: cov-6.0.0, django-4.9.0
collected 1 item

test_example.py .                                               [100%]

========================== 1 passed in 0.01s ==========================
Exception ignored in: <django.core.management.base.OutputWrapper object at 0x10533b760>
Traceback (most recent call last):
  File "/.../.venv/lib/python3.13/site-packages/django/core/management/base.py", line 171, in flush
    self._out.flush()
ValueError: I/O operation on closed file.
Exception ignored in: <django.core.management.base.OutputWrapper object at 0x10549b760>
Traceback (most recent call last):
  File "/.../.venv/lib/python3.13/site-packages/django/core/management/base.py", line 171, in flush
    self._out.flush()
ValueError: I/O operation on closed file.

(-ds=test_example specifies the Django settings module as the test module, so you don’t need a whole project set up.)

After some drilling down, I determined the cause is OutputWrapper instances that are created during BaseCommand.__init__ with references to sys.stdout and sys.stderr. It seems that when they’re deleted, they interact poorly if the underlying file objects have already been closed. pytest’s output caputring installs a mock sys.stdout and closes it after tests are done, but the captured traceback retains a reference to the OutputWrapper until tests finish. When the OutputWrapper is finally garbage collected, the error is logged. Disabling output capturing with pytest -s makes the error go away.

I tried to replicate within Django’s test framework with its output capturing option, --buffer, but it didn’t work. I think it has some differences that mean the error doesn’t appear.

But I did manage to minimize down to this test script, free of pytest and management commands:

import io

from django.core.management.base import OutputWrapper

out = io.TextIOWrapper(io.BytesIO())
wrapper = OutputWrapper(out)
out.close()

Running it shows:

$ python example_simplest.py
Exception ignored in: <django.core.management.base.OutputWrapper object at 0x1049cbb20>
Traceback (most recent call last):
  File "/.../.venv/lib/python3.13/site-packages/django/core/management/base.py", line 172, in flush
ValueError: I/O operation on closed file.

I also found that the error is reproducible on Python < 3.13 when enabling development mode with python -X dev. It turns out the logging was special-cased to development mode within the io module, but this special-casing was removed in Python 3.13 in commit 58a2e0981642dcddf49daa776ff68a43d3498cee. So the error has been there all along, but now it’s more visible.

I think the fix is to stop OutputWrapper from inheriting from TextIOBase, as was added in dc8834cad41aa407f402dc54788df3cd37ab3e22. That commit was focused on removing force_str() calls and it’s not clear why the inheritance was added. But it seems that the path from `IOBase.__del__()` to the custom flush() is what’s causing the error.

Change History (9)

comment:1 by Adam Johnson, 4 days ago

Has patch: set

comment:2 by Adam Johnson, 4 days ago

Owner: set to Adam Johnson
Status: newassigned

comment:3 by Natalia Bidart, 4 days ago

Needs tests: set
Triage Stage: UnreviewedAccepted
Type: BugCleanup/optimization

Thank you Adam for the very detailed ticket report. I think I have followed your rationale and I have reproduced the example in the Python terminal. Accepting on the basis that we can add a test to the proposed PR with something similar to what is proposed as the pure python script. Do you think you could try to work a test out?

comment:4 by Natalia Bidart, 4 days ago

I wonder if the fix for this shouldn't be pushing forward #21429.

comment:5 by Adam Johnson, 4 days ago

Needs tests: unset

Test added!

comment:6 by Natalia Bidart, 3 days ago

Triage Stage: AcceptedReady for checkin

comment:7 by GitHub <noreply@…>, 3 days ago

Resolution: fixed
Status: assignedclosed

In ec0e784f:

Fixed #36056 -- Made OutputWrapper a virtual subclass of TextIOBase.

This fixes the ignored exception in self._out.flush() from
django.core.management.base.OutputWrapper:
ValueError: I/O operation on closed file.

comment:8 by Adam Johnson, 10 hours ago

Thank you for merging.

I would like this to be backported to Django 5.1, although I can see that it requires a little generosity interpreting the policy.

On Python 3.13 and pytest, *any* test running a failing management command triggers this error. On the two projects I’ve seen, that means 10+ copies of this exception in the output of a full test run. Also, there’s no easy way to silence the error.

It’s an exception, and we could consider it a “Crashing bug”, given it crashes part of garbage collection but not the full process.

comment:9 by Natalia Bidart, 7 hours ago

Adam, let me ponder and discuss with other Fellows and I'll get back to you.

Note: See TracTickets for help on using tickets.
Back to Top