Opened 22 months ago

Closed 22 months ago

Last modified 22 months 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 (11)

comment:1 by Adam Johnson, 22 months ago

Has patch: set

comment:2 by Adam Johnson, 22 months ago

Owner: set to Adam Johnson
Status: new → assigned

comment:3 by Natalia Bidart, 22 months ago

Needs tests: set
Triage Stage: Unreviewed → Accepted
Type: Bug → Cleanup/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, 22 months ago

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

comment:5 by Adam Johnson, 22 months ago

Needs tests: unset

Test added!

comment:6 by Natalia Bidart, 22 months ago

Triage Stage: Accepted → Ready for checkin

comment:7 by GitHub <noreply@…>, 22 months ago

Resolution: → fixed
Status: assigned → closed

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, 22 months 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, 22 months ago

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

comment:10 by Natalia Bidart, 22 months ago

Hey Adam, while I sympathize with your request, we won't backport this fix. There is some further rationale in ​this related forum post.

comment:11 by Adam Johnson, 22 months ago

Okay, well it’s fair that you don’t want to assume the risk. I have blogged about a workaround: ​https://adamj.eu/tech/2025/01/08/django-silence-exception-ignored-outputwrapper/

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