Keep full-logging alive in granian workers after post-fork dictConfig

Merged
MA
2mo ago
+180-11

Type of change

  • Bug fix (non-breaking change which fixes an issue)

Changes To Core Features:

  • Have you added an explanation of what your changes do and why you'd like us to include them?
  • Have you written new tests for your core changes, as applicable?
  • Have you successfully ran tests with your changes locally?

Defect

FINDING-005 from 0.9.9a1 pre-release testing (logging_cli cluster, verifier-confirmed): with REFLEX_ENABLE_FULL_LOGGING, granian's worker startup (granian/server/mp.py::WorkerProcess.wrap_target) runs granian.log.configure_logging -> logging.config.dictConfig before loading the app. Stdlib dictConfig unconditionally runs _clearExistingHandlers(), which closes every handler in the process — including the fork-inherited reflex full-logging FileHandler. Since the handler was opened with mode="w", Python 3.10+ FileHandler.emit refuses to reopen it once closed (it would truncate), so every worker-side record was silently dropped from the log file — precisely the records full logging exists to capture.

Worse, log_file_stream() then returned the closed handler's None stream (despite its comment claiming that could never happen), and the legacy console.print_to_log_file writer's rich.Console(file=None) falls back to stdout: every legacy console call in a worker leaked a duplicated [YYYY-mm-dd HH:MM:SS.ffffff] ... plain-text line, breaking the machine-readable --json output contract (11 non-JSON lines interleaved with JSON records in the repro). Regression introduced by #6863, which routed the legacy file console through the logging FileHandler's stream (0.9.8's file console opened its own append-mode file that dictConfig could not touch).

Fix

All in reflex_base/utils/log.py (+ one line in console.py), no post-fork hook needed — the pipeline now self-heals lazily, which also protects against any application-side dictConfig:

  • _file_handler() truncates the log file explicitly at creation and opens the handler in append mode. The stdlib then reopens a closed mode="a" handler on the next emit, so fork-inherited worker handlers resume writing instead of dropping records; appends are atomic (O_APPEND), letting the CLI parent and the reopened worker copies safely share one file. Per-run truncation semantics are unchanged.
  • log_file_stream() reopens a closed stream under the handler lock instead of handing writers a dead one.
  • The legacy console file writer now holds a stable proxy file object (log_file_proxy()) that resolves the live stream on every write — it can neither fall back to stdout (the --json leak) nor crash with ValueError on a stale closed stream captured before the fork.

Test plan

  • New unit tests in tests/units/reflex_base/utils/test_log.py, written first and shown failing on unfixed main with the exact three failure modes: test_file_handler_survives_external_dictconfig (post-dictConfig record missing from the file), test_log_file_console_targets_file_after_external_close (timestamped line leaked to captured stdout), test_cached_log_file_console_survives_external_close (ValueError: I/O operation on closed file), plus test_file_handler_truncates_previous_run guarding the truncate-then-append semantics. All 52 tests in the module pass with the fix.
  • Real repro: scratch app with an api_transformer route emitting console.info/console.warn/reflex_base.* logger records, REFLEX_ENABLE_FULL_LOGGING=1 REFLEX_LOG_FILE=... reflex run --backend-only under granian with the fork start method (the default on Python <= 3.13; forced via multiprocessing.set_start_method("fork") on this 3.14 dev env, where granian otherwise coerces forkserver to spawn and the bug cannot trigger). Before: 0 worker records in the log file, 6 leaked timestamped stdout lines, and with --json 11 non-JSON lines interleaved. After: all worker records (legacy shim + pipeline) land in the same file as the parent's, 0 leaked lines, and --json stdout is 14/14 valid JSON lines.
  • uv run ruff check . / uv run ruff format . clean; uv run pyright reflex tests and pyright on the touched reflex-base files: 0 errors.

🤖 Generated with Claude Code

https://claude.ai/code/session_01EMjBXPozsNeQNSBZecNH8x

Generated by Claude Code