Skip to content

Fix noisy 'I/O operation on closed file' during test teardown#21096

Merged
zzstoatzz merged 2 commits intomainfrom
fix/safe-stream-handler-teardown-16626
Mar 12, 2026
Merged

Fix noisy 'I/O operation on closed file' during test teardown#21096
zzstoatzz merged 2 commits intomainfrom
fix/safe-stream-handler-teardown-16626

Conversation

@zzstoatzz
Copy link
Collaborator

@zzstoatzz zzstoatzz commented Mar 11, 2026

Closes #16626

Summary

  • Add _SafeStreamHandler to src/prefect/logging/handlers.py — suppresses ValueError from closed streams in handleError()
  • Use it for the debug handler in logging.yml (only serves prefect._internal, no user-facing loggers affected)
  • Add regression tests

This is a stdlib logging.StreamHandler + daemon thread race condition. When daemon threads from Prefect's concurrency layer log after pytest closes stderr, the stdlib's handleError() prints noisy --- Logging error --- tracebacks. _SafeStreamHandler silences that specific case.

Why a subclass?

The stdlib StreamHandler.emit() catches ValueError internally and routes it to handleError(), which prints the traceback. There's no configuration point to suppress this — subclassing is the only clean approach.

The subclass is scoped to the single debug handler used by prefect._internal. User-facing loggers (prefect, prefect.flow_runs, prefect.task_runs, etc.) use PrefectConsoleHandler or APILogHandler and are completely unaffected. It's underscore-prefixed to signal it's an internal implementation detail.

Root cause: stdlib reproduction (zero Prefect imports)
"""
Minimal reproduction — pure stdlib, zero dependencies.

A daemon thread logs via a StreamHandler pointed at stderr. When the main
thread closes stderr (simulating pytest teardown), the daemon thread's next
log call hits "I/O operation on closed file" and the stdlib prints a noisy
"--- Logging error ---" traceback.
"""

import io
import logging
import sys
import threading
import time

logger = logging.getLogger("repro")
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(sys.stderr)
handler.setFormatter(logging.Formatter("%(message)s"))
logger.addHandler(handler)


def daemon_work():
    time.sleep(0.1)
    logger.debug("Finished call %r", "get(<dropped>)")


capture = io.StringIO()
real_stderr = sys.stderr

t = threading.Thread(target=daemon_work, daemon=True)
t.start()

# simulate pytest teardown: close stderr while daemon is still alive
closed = io.StringIO()
closed.close()
handler.stream = closed
sys.stderr = capture

t.join()
sys.stderr = real_stderr

output = capture.getvalue()
if "I/O operation on closed file" in output:
    print("BUG REPRODUCED:")
    print(output)
else:
    print("bug not reproduced")
Why not graceful thread shutdown instead?

The concurrency layer's threads (global event loop, run-sync loop, service workers) are daemon threads by design — they're meant to die with the process without blocking exit. The race window is between pytest closing stderr and the interpreter killing daemon threads. We don't control that ordering.

The daemon threads are shutting down; they just sometimes get one last log call in after the stream is gone. _SafeStreamHandler handles that inherent timing gap.

🤖 Generated with Claude Code

The prefect._internal logger's debug handler used a plain
logging.StreamHandler. When background threads from the concurrency
layer logged after pytest closed stderr, the stdlib's handleError()
printed noisy tracebacks. SafeStreamHandler suppresses ValueError
for closed streams while preserving all other error handling.

Closes #16626

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
@github-actions github-actions bot added bug Something isn't working development Tech debt, refactors, CI, tests, and other related work. labels Mar 11, 2026
@codspeed-hq
Copy link

codspeed-hq bot commented Mar 11, 2026

Merging this PR will not alter performance

✅ 2 untouched benchmarks


Comparing fix/safe-stream-handler-teardown-16626 (c7af34f) with main (cfb107d)

Open in CodSpeed

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
@zzstoatzz zzstoatzz added the fix A fix for a bug in an existing feature label Mar 12, 2026
@zzstoatzz zzstoatzz marked this pull request as ready for review March 12, 2026 00:29
@desertaxle
Copy link
Member

Could we solve this issue with a pytest fixture that explicitly stops the daemon threads?

@zzstoatzz
Copy link
Collaborator Author

Could we solve this issue with a pytest fixture that explicitly stops the daemon threads?

@desertaxle i think we could write a fixture that'd resolve it for our CI, but gauging the reactions and report that prompted me coming back to this, that wouldn't help anyone else, so we'd have to document a workaround fixture that everyone would have to adopt. since i'm only changing the debug level here, this felt simpler

@zzstoatzz zzstoatzz merged commit 11576ed into main Mar 12, 2026
75 checks passed
@zzstoatzz zzstoatzz deleted the fix/safe-stream-handler-teardown-16626 branch March 12, 2026 18:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working development Tech debt, refactors, CI, tests, and other related work. fix A fix for a bug in an existing feature

Projects

None yet

Development

Successfully merging this pull request may close these issues.

clean up I/O operation on closed file errors during test suite

2 participants