Skip to content

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

Merged
masenf merged 5 commits into
mainfrom
claude/rel-fix-full-logging-worker
Aug 28, 2026
Merged

Keep full-logging alive in granian workers after post-fork dictConfig#6992
masenf merged 5 commits into
mainfrom
claude/rel-fix-full-logging-worker

Conversation

@masenf

@masenf masenf commented Aug 28, 2026

Copy link
Copy Markdown
Collaborator

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

Review in cubic

With REFLEX_ENABLE_FULL_LOGGING, granian's worker startup runs
logging.config.dictConfig, whose _clearExistingHandlers closes every
fork-inherited handler. The full-logging FileHandler was opened with
mode="w", which the stdlib refuses to reopen once closed (it would
truncate), so every worker-side record was silently dropped from the log
file. Worse, log_file_stream() then returned the closed handler's None
stream, and the legacy console file writer's rich Console(file=None)
fell back to stdout, leaking timestamped plain-text lines that broke the
--json output contract.

Fix: truncate the log file explicitly at handler creation and open the
handler in append mode, so the stdlib reopens it on the next record
(appends are also atomic, letting the CLI parent and reopened worker
copies safely share one file). log_file_stream() now reopens a closed
stream under the handler lock, and the legacy console writes through a
stable proxy that resolves the live stream on every write, so it can
neither leak to stdout nor crash on a stale closed stream.

Found as FINDING-005 in 0.9.9a1 pre-release testing.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01EMjBXPozsNeQNSBZecNH8x
@masenf
masenf requested a review from a team as a code owner August 28, 2026 18:48
@greptile-apps

greptile-apps Bot commented Aug 28, 2026

Copy link
Copy Markdown
Contributor

Greptile Summary

The PR makes full-file logging recover after Granian closes inherited handlers during worker logging reconfiguration.

  • Opens the handler in append mode after explicitly truncating the file at initial creation.
  • Adds a stable stream proxy that resolves and locks the current handler stream for each write or flush.
  • Routes the legacy Rich console through that proxy and adds regression coverage for handler closure and truncation behavior.

Confidence Score: 5/5

The PR appears safe to merge because no blocking failure remains in the eligible follow-up review scope.

No blocking failure remains.

Important Files Changed

Filename Overview
packages/reflex-base/src/reflex_base/utils/log.py Changes file-handler initialization to truncate then append and adds a lock-protected, lazily reopening stream proxy.
packages/reflex-base/src/reflex_base/utils/console.py Routes the cached Rich file console through the stable logging-stream proxy.
tests/units/reflex_base/utils/test_log.py Adds regression tests for external handler closure, cached consoles, stdout isolation, and per-run truncation.
packages/reflex-base/news/+full-logging-worker.bugfix.md Documents restored worker logging and prevention of plain-text leakage into JSON output.

Reviews (3): Last reviewed commit: "Merge remote-tracking branch 'origin/mai..." | Re-trigger Greptile

@codspeed-hq

codspeed-hq Bot commented Aug 28, 2026

Copy link
Copy Markdown

Merging this PR will not alter performance

✅ 32 untouched benchmarks
⏩ 8 skipped benchmarks1


Comparing claude/rel-fix-full-logging-worker (dd5272e) with main (7427617)

Open in CodSpeed

Footnotes

  1. 8 benchmarks were skipped, so the baseline results were used instead. If they were deleted from the codebase, click here and archive them to remove them from the performance reports.

@masenf masenf added this to the v0.9.9 milestone Aug 28, 2026

@cubic-dev-ai cubic-dev-ai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All reported issues were addressed across 4 files

Reply with feedback, questions, or to request a fix.

Re-trigger cubic

Comment thread packages/reflex-base/src/reflex_base/utils/log.py Outdated
claude and others added 4 commits August 28, 2026 19:22
The changelog gate checks each package's own news/ directory, and the
changed source lives in packages/reflex-base/, so the fragment must also
exist there (keeping the root copy, as sibling PRs do). Condense both
fragments to two sentences to match the style of neighboring fragments,
and note at the log_file_stream() reopen site that FileHandler._open is
private stdlib API relied on deliberately.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01EMjBXPozsNeQNSBZecNH8x
@masenf
masenf merged commit 34bdfc3 into main Aug 28, 2026
111 checks passed
@masenf
masenf deleted the claude/rel-fix-full-logging-worker branch August 28, 2026 20:05
masenf pushed a commit that referenced this pull request Aug 28, 2026
…-context-refactor-jv3pig

Picks up #6987, #6990, #6989, #6992 and #6993. Clean auto-merge; main's
``templates.py`` edit is again in the Vite config template, away from
``render_iterable_tag``.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants