From 8b7276ccdfd8bb1d186a66930c2933a638356ff5 Mon Sep 17 00:00:00 2001 From: Farhan Date: Tue, 11 Aug 2026 01:20:25 +0500 Subject: [PATCH 01/11] feat(log): add stdlib logging pipeline in reflex_base.utils.log Standard python logging with per-module loggers: rich-rendering console handler preserving the legacy colors, JSON-lines handler behind REFLEX_LOG_JSON, record dedupe, and file logging. LogLevel gains a correct total ordering (the str mixin compared alphabetically) and to_logging_level(). console.py delegates set_log_level into the pipeline and respects JSON mode in print/rule/status/progress; reflex bootstraps the reflex-owned loggers on import. --- news/+eng-10963-log-pipeline.feature.md | 1 + .../news/+eng-10963-log-pipeline.feature.md | 1 + .../src/reflex_base/constants/base.py | 60 +- .../src/reflex_base/environment.py | 10 +- .../src/reflex_base/utils/console.py | 46 +- .../reflex-base/src/reflex_base/utils/log.py | 679 ++++++++++++++++++ pyi_hashes.json | 2 +- pyproject.toml | 1 + reflex/__init__.py | 13 +- reflex/utils/log.py | 4 + tests/units/conftest.py | 20 + tests/units/reflex_base/utils/test_log.py | 347 +++++++++ tests/units/test_environment.py | 9 +- 13 files changed, 1170 insertions(+), 23 deletions(-) create mode 100644 news/+eng-10963-log-pipeline.feature.md create mode 100644 packages/reflex-base/news/+eng-10963-log-pipeline.feature.md create mode 100644 packages/reflex-base/src/reflex_base/utils/log.py create mode 100644 reflex/utils/log.py create mode 100644 tests/units/reflex_base/utils/test_log.py diff --git a/news/+eng-10963-log-pipeline.feature.md b/news/+eng-10963-log-pipeline.feature.md new file mode 100644 index 00000000000..564a0540d49 --- /dev/null +++ b/news/+eng-10963-log-pipeline.feature.md @@ -0,0 +1 @@ +Framework logging now flows through standard python `logging` with per-module loggers (`reflex_base.utils.log`, re-exported as `reflex.utils.log`), bootstrapped on `import reflex`. Rich colored output is preserved at the sink, and `REFLEX_LOG_JSON` emits machine-readable JSON-lines records. `--loglevel critical` no longer prints the system-info banner (broken `LogLevel` string-compare ordering fixed). diff --git a/packages/reflex-base/news/+eng-10963-log-pipeline.feature.md b/packages/reflex-base/news/+eng-10963-log-pipeline.feature.md new file mode 100644 index 00000000000..24f955b45b3 --- /dev/null +++ b/packages/reflex-base/news/+eng-10963-log-pipeline.feature.md @@ -0,0 +1 @@ +Added `reflex_base.utils.log`: a standard python logging pipeline with a rich-rendering console handler (legacy colors preserved), a JSON-lines handler behind `REFLEX_LOG_JSON`, record deduplication, and file logging. `LogLevel` gained a correct total ordering and `to_logging_level()`, and the interactive console helpers (`print`/`rule`/`status`/`progress`) now respect JSON mode. diff --git a/packages/reflex-base/src/reflex_base/constants/base.py b/packages/reflex-base/src/reflex_base/constants/base.py index f5b235566b2..b5c9079517e 100644 --- a/packages/reflex-base/src/reflex_base/constants/base.py +++ b/packages/reflex-base/src/reflex_base/constants/base.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging import platform from enum import Enum from importlib import metadata @@ -248,6 +249,19 @@ def from_string(cls, level: str | None) -> LogLevel | None: except KeyError: return None + # The str mixin supplies alphabetical comparisons, so all four operators + # must be overridden to compare by verbosity rank instead. + def __lt__(self, other: LogLevel) -> bool: + """Compare log levels. + + Args: + other: The other log level. + + Returns: + True if the log level is less verbose than the other log level. + """ + return _LOG_LEVEL_RANK[self] < _LOG_LEVEL_RANK[other] + def __le__(self, other: LogLevel) -> bool: """Compare log levels. @@ -257,8 +271,39 @@ def __le__(self, other: LogLevel) -> bool: Returns: True if the log level is less than or equal to the other log level. """ - levels = list(LogLevel) - return levels.index(self) <= levels.index(other) + return _LOG_LEVEL_RANK[self] <= _LOG_LEVEL_RANK[other] + + def __gt__(self, other: LogLevel) -> bool: + """Compare log levels. + + Args: + other: The other log level. + + Returns: + True if the log level is more verbose-restrictive than the other. + """ + return _LOG_LEVEL_RANK[self] > _LOG_LEVEL_RANK[other] + + def __ge__(self, other: LogLevel) -> bool: + """Compare log levels. + + Args: + other: The other log level. + + Returns: + True if the log level is greater than or equal to the other. + """ + return _LOG_LEVEL_RANK[self] >= _LOG_LEVEL_RANK[other] + + def to_logging_level(self) -> int: + """Map this level to a stdlib logging level number. + + DEFAULT acts as a threshold equivalent to INFO. + + Returns: + The stdlib logging level. + """ + return _LOGGING_LEVELS[self] def subprocess_level(self): """Return the log level for the subprocess. @@ -269,6 +314,17 @@ def subprocess_level(self): return self if self != LogLevel.DEFAULT else LogLevel.WARNING +_LOG_LEVEL_RANK = {level: rank for rank, level in enumerate(LogLevel)} +_LOGGING_LEVELS = { + LogLevel.DEBUG: logging.DEBUG, + LogLevel.DEFAULT: logging.INFO, + LogLevel.INFO: logging.INFO, + LogLevel.WARNING: logging.WARNING, + LogLevel.ERROR: logging.ERROR, + LogLevel.CRITICAL: logging.CRITICAL, +} + + # Server socket configuration variables POLLING_MAX_HTTP_BUFFER_SIZE = 1000 * 1000 diff --git a/packages/reflex-base/src/reflex_base/environment.py b/packages/reflex-base/src/reflex_base/environment.py index 359effad060..74993868c32 100644 --- a/packages/reflex-base/src/reflex_base/environment.py +++ b/packages/reflex-base/src/reflex_base/environment.py @@ -5,6 +5,7 @@ import dataclasses import enum import importlib +import logging import os from collections.abc import Sequence from functools import lru_cache @@ -27,6 +28,8 @@ from reflex_base.utils.exceptions import EnvironmentVarValueError from reflex_base.utils.types import GenericType, is_union, value_inside_optional +logger = logging.getLogger(__name__) + def get_default_value_for_field(field: dataclasses.Field) -> Any: """Get the default value for a field. @@ -705,6 +708,9 @@ class EnvironmentVariables: # Enable full logging of debug messages to reflex user directory. REFLEX_ENABLE_FULL_LOGGING: EnvVar[bool] = env_var(False) + # Emit logs as machine-readable JSON records instead of rich console output. + REFLEX_LOG_JSON: EnvVar[bool] = env_var(False) + # Whether to enable hot module replacement VITE_HMR: EnvVar[bool] = env_var(True) @@ -781,13 +787,11 @@ def _load_dotenv_from_files(files: list[Path]): Args: files: A list of Path objects representing the environment variable files. """ - from reflex_base.utils import console - if not files: return if load_dotenv is None: - console.error( + logger.error( """The `python-dotenv` package is required to load environment variables from a file. Run `pip install "python-dotenv>=1.1.0"`.""" ) return diff --git a/packages/reflex-base/src/reflex_base/utils/console.py b/packages/reflex-base/src/reflex_base/utils/console.py index 6d4d3bf16d8..0fe9c80ebcd 100644 --- a/packages/reflex-base/src/reflex_base/utils/console.py +++ b/packages/reflex-base/src/reflex_base/utils/console.py @@ -6,19 +6,21 @@ import datetime import functools import inspect -import os import shutil import sys import time +from collections.abc import Sequence from pathlib import Path from types import FrameType, ModuleType from rich.console import Console from rich.progress import MofNCompleteColumn, Progress, TaskID, TimeElapsedColumn from rich.prompt import Prompt +from rich.table import Table from reflex_base.constants import LogLevel from reflex_base.constants.base import Reflex +from reflex_base.utils import log as _log from reflex_base.utils.decorator import once # Console for pretty printing. @@ -58,19 +60,11 @@ def set_log_level(log_level: LogLevel | None): Args: log_level: The log level to set. - - Raises: - TypeError: If the log level is a string. """ if log_level is None: return - if not isinstance(log_level, LogLevel): - msg = f"log_level must be a LogLevel enum value, got {log_level} of type {type(log_level)} instead." - raise TypeError(msg) + _log.set_log_level(log_level) global _LOG_LEVEL - if log_level != _LOG_LEVEL: - # Set the loglevel persistenly for subprocesses. - os.environ["REFLEX_LOGLEVEL"] = log_level.value _LOG_LEVEL = log_level @@ -91,6 +85,9 @@ def print(msg: str, *, dedupe: bool = False, **kwargs): dedupe: If True, suppress multiple console logs of print message. kwargs: Keyword arguments to pass to the print function. """ + if _log.is_json_mode(): + _log.emit_json_print(msg, dedupe=dedupe) + return if dedupe: if msg in _EMITTED_PRINTS: return @@ -106,6 +103,9 @@ def _print_stderr(msg: str, *, dedupe: bool = False, **kwargs): dedupe: If True, suppress multiple console logs of print message. kwargs: Keyword arguments to pass to the print function. """ + if _log.is_json_mode(): + _log.emit_json_print(msg, dedupe=dedupe, stderr=True) + return if dedupe: if msg in _EMITTED_PRINTS: return @@ -241,6 +241,8 @@ def rule(title: str, **kwargs): title: The title of the rule. kwargs: Keyword arguments to pass to the print function. """ + if _log.is_json_mode(): + return _console.rule(title, **kwargs) @@ -417,6 +419,27 @@ def ask( ) +def print_table( + tabular_data: list[list[str]], + headers: Sequence[str] = (), +) -> None: + """Print a table to the console. + + Args: + tabular_data: The data to print in tabular format. + headers: The headers for the table. + """ + table = Table() + + for column in headers: + table.add_column(column) + + for row in tabular_data: + table.add_row(*row) + + _console.print(table) + + def progress(): """Create a new progress bar. @@ -427,6 +450,7 @@ def progress(): *Progress.get_default_columns()[:-1], MofNCompleteColumn(), TimeElapsedColumn(), + disable=_log.is_json_mode(), ) @@ -440,6 +464,8 @@ def status(*args, **kwargs): Returns: A new status. """ + if _log.is_json_mode(): + return _log._quiet_console.status(*args, **kwargs) return _console.status(*args, **kwargs) diff --git a/packages/reflex-base/src/reflex_base/utils/log.py b/packages/reflex-base/src/reflex_base/utils/log.py new file mode 100644 index 00000000000..7bd172a1e6f --- /dev/null +++ b/packages/reflex-base/src/reflex_base/utils/log.py @@ -0,0 +1,679 @@ +"""Standard-library logging pipeline with rich rendering and JSON output. + +Reflex modules log through plain ``logging.getLogger(__name__)`` loggers. +This module owns the sinks: a rich-rendering console handler (colored, same +look as the legacy ``console`` helpers), a JSON-lines handler for machine +consumption (``REFLEX_LOG_JSON`` / ``--json``), and an optional file handler +(``REFLEX_ENABLE_FULL_LOGGING`` / ``REFLEX_LOG_FILE``). +""" + +from __future__ import annotations + +import contextlib +import datetime +import functools +import json +import logging +import os +import shutil +import sys +import time +from pathlib import Path +from types import FrameType, ModuleType +from typing import TYPE_CHECKING + +from rich.console import Console +from rich.errors import MarkupError +from rich.text import Text + +from reflex_base.constants import LogLevel +from reflex_base.constants.base import Reflex +from reflex_base.utils.decorator import once + +if TYPE_CHECKING: + from collections.abc import Hashable, Iterator + +# Level between INFO and WARNING for user-facing success messages. +SUCCESS = 25 +logging.addLevelName(SUCCESS, "SUCCESS") + +# Package-root loggers that receive the reflex handlers. Every distribution +# that logs needs its root here: loggers do not propagate across the +# ``reflex_*`` top-level names, so an omitted root escapes the pipeline +# entirely (no styling, no level gating, no JSON records, no file capture). +ROOT_LOGGER_NAMES = ( + "reflex", + "reflex_base", + "reflex_cli", + "reflex_components_core", + "reflex_components_dataeditor", + "reflex_components_lucide", + "reflex_components_plotly", + "reflex_components_react_player", +) + +# Consoles for pretty printing (shared with reflex_base.utils.console). +_console = Console(highlight=False) +_console_stderr = Console(stderr=True, highlight=False) + +# Console that renders nowhere, backing interactive rich features in JSON mode. +_quiet_console = Console(quiet=True) + +# The current log level. +_log_level = LogLevel.INFO + +# Formatter kept only for its exception rendering, which is stateless. +_EXC_FORMATTER = logging.Formatter() + +# (style, prefix) per level for the rich console sink. +_LEVEL_STYLES: dict[int, tuple[str, str]] = { + logging.DEBUG: ("purple", "Debug: "), + logging.INFO: ("cyan", "Info: "), + SUCCESS: ("green", "Success: "), + logging.WARNING: ("orange1", "Warning: "), + logging.ERROR: ("red", ""), + logging.CRITICAL: ("red", ""), +} + +# Style and prefix for records carrying ``kind="deprecation"``. +DEPRECATION_STYLE = ("yellow", "DeprecationWarning: ") + + +def style_for_level(levelno: int) -> tuple[str, str]: + """Resolve the rich style and message prefix for a log level. + + Args: + levelno: The stdlib logging level number. + + Returns: + A (style, prefix) tuple. + """ + levelno = min(logging.CRITICAL, max(logging.DEBUG, levelno)) + # Round down to the nearest known level. + while levelno not in _LEVEL_STYLES: + levelno -= 1 + return _LEVEL_STYLES[levelno] + + +def _style_for(record: logging.LogRecord) -> tuple[str, str]: + """Resolve the rich style and message prefix for a record. + + Args: + record: The log record being rendered. + + Returns: + A (style, prefix) tuple. + """ + if getattr(record, "kind", None) == "deprecation": + return DEPRECATION_STYLE + return style_for_level(record.levelno) + + +def strip_markup(msg: str) -> str: + """Remove rich markup tags from a message. + + Args: + msg: The message, possibly containing rich markup. + + Returns: + The plain-text message. + """ + if "[" not in msg: + return msg + try: + return Text.from_markup(msg).plain + except MarkupError: + return msg + + +class DedupeFilter(logging.Filter): + """Drop repeat records that opted into deduplication.""" + + def __init__(self): + """Initialize the filter with an empty seen-set.""" + super().__init__() + self.seen: set = set() + + def register(self, key: Hashable) -> bool: + """Record a dedupe key, reporting whether it is new. + + Args: + key: A hashable dedupe key. + + Returns: + True the first time the key is seen, False afterwards. + """ + if key in self.seen: + return False + self.seen.add(key) + return True + + def filter(self, record: logging.LogRecord) -> bool: + """Decide whether a record should be emitted. + + Args: + record: The log record. + + Returns: + False if an identical record was already emitted with dedupe set. + """ + key = getattr(record, "dedupe_key", None) + if key is None: + if not getattr(record, "dedupe", False): + return True + key = (record.levelno, record.getMessage()) + return self.register(key) + + +class RichConsoleHandler(logging.Handler): + """Render log records with rich, matching the legacy console look.""" + + def emit(self, record: logging.LogRecord): + """Print a record to the terminal. + + Args: + record: The log record. + """ + try: + style, prefix = _style_for(record) + console = _console_stderr if record.levelno >= logging.ERROR else _console + # Records may carry a rich Progress to print through, so the + # message lands above an active progress bar. + progress = getattr(record, "progress", None) + if progress is not None: + console = progress.console + end = getattr(record, "end", "\n") + console.print(f"{prefix}{record.getMessage()}", style=style, end=end) + if record.exc_info and record.exc_info[0] is not None: + # Tracebacks may contain user data; never parse them as markup. + console.print(self.format_exception(record), style=style, markup=False) + except Exception: + self.handleError(record) + + def format_exception(self, record: logging.LogRecord) -> str: + """Format a record's exception info as text. + + Args: + record: The log record with exc_info set. + + Returns: + The formatted traceback. + """ + return _EXC_FORMATTER.formatException(record.exc_info) # pyright: ignore[reportArgumentType] + + +def _write_json(payload: dict, *, stderr: bool): + """Write one JSON record to the output stream. + + Args: + payload: The record fields. + stderr: Whether the record targets stderr. + """ + stream = sys.stderr if stderr else sys.stdout + stream.write(json.dumps(payload, default=str) + "\n") + stream.flush() + + +class JsonHandler(logging.Handler): + """Emit one JSON object per record for machine consumption.""" + + extra_fields = ( + "feature_name", + "deprecation_version", + "removal_version", + "kind", + ) + + def emit(self, record: logging.LogRecord): + """Write a record as a JSON line to stdout or stderr. + + Args: + record: The log record. + """ + try: + payload = { + "timestamp": datetime.datetime.fromtimestamp( + record.created, tz=datetime.timezone.utc + ).isoformat(), + "level": logging.getLevelName(record.levelno).lower(), + "logger": record.name, + "message": strip_markup(record.getMessage()), + "location": f"{record.pathname}:{record.lineno}", + "pid": record.process, + } + for field in self.extra_fields: + value = getattr(record, field, None) + if value is not None: + payload[field] = value + if record.exc_info and record.exc_info[0] is not None: + payload["exception"] = _EXC_FORMATTER.formatException( + record.exc_info # pyright: ignore[reportArgumentType] + ) + _write_json(payload, stderr=record.levelno >= logging.ERROR) + except Exception: + self.handleError(record) + + +class _StripMarkupFormatter(logging.Formatter): + """Formatter that removes rich markup from messages.""" + + def format(self, record: logging.LogRecord) -> str: + """Format a record with markup stripped. + + Args: + record: The log record. + + Returns: + The formatted line. + """ + msg, args = record.msg, record.args + try: + record.msg = strip_markup(record.getMessage()) + record.args = () + return super().format(record) + finally: + record.msg, record.args = msg, args + + +def _log_file_path() -> Path: + """Resolve the path of the full-logging file. + + Returns: + The log file path (parent directory created). + """ + from reflex_base.environment import environment + + if env_log_file := environment.REFLEX_LOG_FILE.get(): + return env_log_file + subseconds = int((time.time() % 1) * 1000) + timestamp = time.strftime("%Y-%m-%d_%H-%M-%S") + f"_{subseconds:03d}" + log_file = Reflex.DIR / "logs" / (timestamp + ".log") + log_file.parent.mkdir(parents=True, exist_ok=True) + return log_file + + +@once +def _file_handler() -> logging.FileHandler: + """Create the full-logging file handler. + + Returns: + A file handler writing every record with markup stripped. + """ + handler = logging.FileHandler(_log_file_path(), mode="w", encoding="utf-8") + handler.setFormatter( + _StripMarkupFormatter("[{asctime}] {levelname}: {message}", style="{") + ) + return handler + + +@once +def _console_handler() -> RichConsoleHandler: + """Create the rich console handler. + + Returns: + The handler, with the dedupe filter attached. + """ + handler = RichConsoleHandler() + handler.addFilter(_dedupe_filter()) + return handler + + +@once +def _json_handler() -> JsonHandler: + """Create the JSON-lines handler. + + Returns: + The handler, with the dedupe filter attached. + """ + handler = JsonHandler() + handler.addFilter(_dedupe_filter()) + return handler + + +@once +def _dedupe_filter() -> DedupeFilter: + """Create the shared dedupe filter. + + Returns: + The dedupe filter used by the console and JSON handlers. + """ + return DedupeFilter() + + +def is_json_mode() -> bool: + """Check whether logs should be emitted as JSON records. + + Returns: + True if REFLEX_LOG_JSON is enabled. + """ + from reflex_base.environment import environment + + return environment.REFLEX_LOG_JSON.get() + + +def set_json_mode(enabled: bool): + """Enable or disable machine-readable JSON log output. + + Sets the environment variable so subprocesses inherit the mode, then + re-attaches the sinks. + + Args: + enabled: Whether to emit JSON records. + """ + from reflex_base.environment import environment + + environment.REFLEX_LOG_JSON.set(enabled) + configure() + + +def dedupe_once(key: Hashable) -> bool: + """Register a dedupe key, reporting whether it is new. + + Args: + key: A hashable dedupe key. + + Returns: + True the first time the key is seen, False afterwards. + """ + return _dedupe_filter().register(key) + + +def emit_json_print(msg: str, *, dedupe: bool = False, stderr: bool = False): + """Emit a plain console message as a JSON record. + + Used by ``console.print`` in JSON mode so the output stream stays + machine-readable. Not routed through a logger: plain prints are not + level-gated. + + Args: + msg: The message. + dedupe: If True, suppress repeats of the same message. + stderr: Whether the message targets stderr. + """ + if dedupe and not dedupe_once(("print", msg)): + return + _write_json( + { + "timestamp": datetime.datetime.now(tz=datetime.timezone.utc).isoformat(), + "level": "info", + "logger": "reflex.console", + "message": strip_markup(msg), + "pid": os.getpid(), + }, + stderr=stderr, + ) + + +_configured = False +_active_file_handler: logging.FileHandler | None = None + + +class _BootstrapHandler(logging.Handler): + """Attach the real sinks on the first record, then replay it through them.""" + + def handle(self, record: logging.LogRecord) -> bool: + """Configure the pipeline and hand the record to the real sinks. + + Args: + record: The log record. + + Returns: + True, matching the Handler.handle contract. + """ + if _configured: + # configure() detaches this handler, so reaching here means it + # failed to do so. Drop the record rather than recurse. + return True + configure() + logging.getLogger(record.name).handle(record) + return True + + +_bootstrap_handler = _BootstrapHandler() + + +def bootstrap(): + """Claim the reflex loggers without importing the environment machinery. + + ``configure`` needs :mod:`reflex_base.environment`, which drags in the + config and plugin stack (and with it pandas and plotly). Importing that at + ``import reflex`` time would defeat the package's lazy loading, so the + sinks are attached on the first record instead. The permissive logger level + keeps records that a later ``configure`` may want; the sink's own level + does the real gating. + """ + for name in ROOT_LOGGER_NAMES: + logger = logging.getLogger(name) + logger.propagate = False + logger.setLevel(logging.DEBUG) + logger.addHandler(_bootstrap_handler) + + +def configure(): + """Attach the reflex handlers to the reflex package-root loggers. + + Idempotent: handler instances are cached and re-attached, never stacked. + Only reflex-owned loggers are touched (propagation to the root logger is + disabled), so a user application's own logging setup is unaffected. + """ + global _active_file_handler, _configured + from reflex_base.environment import environment + + json_mode = environment.REFLEX_LOG_JSON.get() + sink, other = ( + (_json_handler(), _console_handler()) + if json_mode + else (_console_handler(), _json_handler()) + ) + sink.setLevel(_log_level.to_logging_level()) + full_logging = environment.REFLEX_ENABLE_FULL_LOGGING.get() + file_handler = _active_file_handler + if full_logging: + file_handler = _active_file_handler = _file_handler() + logger_level = logging.DEBUG if full_logging else _log_level.to_logging_level() + # addHandler/removeHandler are no-ops when the handler is already in the + # desired state, so no membership checks are needed here. + for name in ROOT_LOGGER_NAMES: + logger = logging.getLogger(name) + logger.propagate = False + logger.setLevel(logger_level) + logger.removeHandler(_bootstrap_handler) + logger.removeHandler(other) + logger.addHandler(sink) + if file_handler is not None: + if full_logging: + logger.addHandler(file_handler) + else: + logger.removeHandler(file_handler) + _configured = True + + +def ensure_configured(): + """Configure the logging pipeline if it has not been configured yet.""" + if not _configured: + configure() + + +def set_log_level(log_level: LogLevel | None): + """Set the log level. + + Args: + log_level: The log level to set. + + Raises: + TypeError: If the log level is not a LogLevel enum value. + """ + if log_level is None: + return + if not isinstance(log_level, LogLevel): + msg = f"log_level must be a LogLevel enum value, got {log_level} of type {type(log_level)} instead." + raise TypeError(msg) + global _log_level + if log_level != _log_level: + # Set the loglevel persistently for subprocesses. + os.environ["REFLEX_LOGLEVEL"] = log_level.value + _log_level = log_level + configure() + + +def get_log_level() -> LogLevel: + """Get the current log level. + + Returns: + The current log level. + """ + return _log_level + + +def is_debug() -> bool: + """Check if the log level is debug. + + Returns: + True if the log level is debug. + """ + return _log_level <= LogLevel.DEBUG + + +@contextlib.contextmanager +def timing(logger: logging.Logger, msg: str) -> Iterator[None]: + """Time a block of code and log the duration at debug level. + + Args: + logger: The logger to emit the timing record on. + msg: The message to display. + + Yields: + None. + """ + start = time.time() + try: + yield + finally: + logger.debug("[white]\\[timing] %s: %.2fs[/white]", msg, time.time() - start) + + +@once +def _exclude_paths_from_frame_info() -> list[Path]: + import importlib.util + + import click + import granian + import socketio + import typing_extensions + + import reflex_base + + try: + import reflex as rx + except ImportError: + rx = None + + # Exclude utility modules that should never be the source of deprecated reflex usage. + exclude_modules: list[ModuleType | None] = [ + click, + rx, + typing_extensions, + socketio, + granian, + reflex_base, + ] + + modules_paths = [file for m in exclude_modules if m and (file := m.__file__)] + [ + spec.origin + for m in [*sys.builtin_module_names, *sys.stdlib_module_names] + if (spec := importlib.util.find_spec(m)) and spec.origin + ] + exclude_roots = [ + p.parent.resolve() if (p := Path(file)).name == "__init__.py" else p.resolve() + for file in modules_paths + ] + # Specifically exclude the reflex cli module. + if reflex_bin := shutil.which(b"reflex"): + exclude_roots.append(Path(reflex_bin.decode())) + + return exclude_roots + + +@functools.cache +def _is_framework_filename(filename: str) -> bool: + """Check if a code filename belongs to an excluded framework/stdlib root. + + Cached per filename: module file locations do not move within a process, + but resolving a path and comparing it against every exclude root is far + too expensive to repeat for each frame on every deprecation check. + + Args: + filename: The ``co_filename`` of a frame's code object. + + Returns: + Whether the file lives under one of the excluded framework roots. + """ + frame_path = Path(filename).resolve() + return any( + frame_path.is_relative_to(root) for root in _exclude_paths_from_frame_info() + ) + + +def _get_first_non_framework_frame() -> FrameType | None: + frame = sys._getframe() + while frame := frame and frame.f_back: + if not _is_framework_filename(frame.f_code.co_filename): + break + return frame + + +_deprecation_logger = logging.getLogger("reflex.deprecation") + + +def deprecate( + *, + feature_name: str, + reason: str, + deprecation_version: str, + removal_version: str, + dedupe: bool = True, + **kwargs, +): + """Log a deprecation warning. + + Args: + feature_name: The feature to deprecate. + reason: The reason for deprecation. + deprecation_version: The version the feature was deprecated + removal_version: The version the deprecated feature will be removed + dedupe: If True, suppress multiple warnings of the same deprecation. + kwargs: Ignored legacy print kwargs. + """ + del kwargs + dedupe_key = feature_name + loc = "" + + # See if we can find where the deprecation exists in "user code" + origin_frame = _get_first_non_framework_frame() + if origin_frame is not None: + filename = Path(origin_frame.f_code.co_filename) + cwd = Path.cwd() + if filename.is_relative_to(cwd): + filename = filename.relative_to(cwd) + loc = f" ({filename}:{origin_frame.f_lineno})" + dedupe_key = f"{dedupe_key} {loc}" + + # Claim the key up front so repeat warnings skip formatting and emission + # entirely, rather than building a record for the filter to drop. + if dedupe and not dedupe_once(f"deprecation:{dedupe_key}"): + return + + ensure_configured() + msg = ( + f"{feature_name} has been deprecated in version {deprecation_version}. {reason.rstrip('.').lstrip('. ')}. It will be completely " + f"removed in {removal_version}.{loc}" + ) + _deprecation_logger.warning( + msg, + extra={ + "kind": "deprecation", + "feature_name": feature_name, + "deprecation_version": deprecation_version, + "removal_version": removal_version, + }, + ) diff --git a/pyi_hashes.json b/pyi_hashes.json index f83a2da704d..eb5902a8e82 100644 --- a/pyi_hashes.json +++ b/pyi_hashes.json @@ -118,7 +118,7 @@ "packages/reflex-components-recharts/src/reflex_components_recharts/polar.pyi": "99ebcfc07868061bdc3c2010d85a153f", "packages/reflex-components-recharts/src/reflex_components_recharts/recharts.pyi": "4f6c26f8c76543cc41e2b9dc400ece8a", "packages/reflex-components-sonner/src/reflex_components_sonner/toast.pyi": "f170ac685b6ba5892370166c80684db3", - "reflex/__init__.pyi": "56385a4f0d9431eb0056dbc5553a58f9", + "reflex/__init__.pyi": "61b2cc37c3d2473c99f3023c59627d51", "reflex/components/__init__.pyi": "9facd05a776d0641432696bbf8e34388", "reflex/experimental/memo.pyi": "bc8b48357bef580e70a5881b65d3d3f7" } diff --git a/pyproject.toml b/pyproject.toml index 4a3759b3775..2638de9c41b 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -219,6 +219,7 @@ lint.ignore = [ "TC", "TD", "TRY0", + "TRY400", # User-facing errors deliberately omit tracebacks; debug logs carry diagnostics where appropriate. ] lint.pydocstyle.convention = "google" lint.flake8-bugbear.extend-immutable-calls = [ diff --git a/reflex/__init__.py b/reflex/__init__.py index 6b23b495d3e..b6d53cac6a0 100644 --- a/reflex/__init__.py +++ b/reflex/__init__.py @@ -87,14 +87,21 @@ import sys from reflex_base.utils import lazy_loader +from reflex_base.utils import log as _log + +# Claim the reflex loggers so records render styled even before any config is +# loaded (only reflex-owned loggers are touched). The sinks themselves attach +# on the first record, keeping this import cheap. +_log.bootstrap() +del _log if sys.version_info < (3, 11): - from reflex_base.utils import console + import logging - console.warn( + logging.getLogger(__name__).warning( "Reflex support for Python 3.10 is deprecated and will be removed in a future release. Please upgrade to Python 3.11 or higher for continued support." ) - del console + del logging del sys from reflex_components_radix.mappings import RADIX_MAPPING # noqa: E402 diff --git a/reflex/utils/log.py b/reflex/utils/log.py new file mode 100644 index 00000000000..e5f267e2b3a --- /dev/null +++ b/reflex/utils/log.py @@ -0,0 +1,4 @@ +# pyright: reportWildcardImportFromLibrary=false +"""Re-export from reflex_base.""" + +from reflex_base.utils.log import * # pragma: no cover diff --git a/tests/units/conftest.py b/tests/units/conftest.py index 8ef4232fbc7..6b5ea66705d 100644 --- a/tests/units/conftest.py +++ b/tests/units/conftest.py @@ -1,5 +1,6 @@ """Test fixtures.""" +import logging import platform import traceback import uuid @@ -14,6 +15,7 @@ from reflex_base.event.context import EventContext from reflex_base.event.processor import BaseStateEventProcessor, EventProcessor from reflex_base.registry import RegistrationContext +from reflex_base.utils import log from reflex.app import App from reflex.istate.manager import StateManager @@ -45,6 +47,24 @@ def _isolate_app_in_context() -> Generator[None, None, None]: object.__setattr__(ctx, "_app", None) +@pytest.fixture(autouse=True) +def _capture_reflex_logs(caplog): + """Attach pytest's capture handler to Reflex package loggers. + + The logging pipeline deliberately disables propagation at package roots, + while pytest normally captures records from the process root logger. + + Yields: + None. + """ + loggers = [logging.getLogger(name) for name in log.ROOT_LOGGER_NAMES] + for logger in loggers: + logger.addHandler(caplog.handler) + yield + for logger in loggers: + logger.removeHandler(caplog.handler) + + @pytest.fixture def app() -> App: """A base app. diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py new file mode 100644 index 00000000000..a2e48f1f303 --- /dev/null +++ b/tests/units/reflex_base/utils/test_log.py @@ -0,0 +1,347 @@ +"""Tests for the standard logging pipeline in reflex_base.utils.log.""" + +import json +import logging +from unittest import mock + +import pytest +from reflex_base.constants import LogLevel +from reflex_base.utils import console, log + +logger = logging.getLogger("reflex_base.tests.logs") + + +@pytest.fixture(autouse=True) +def clean_pipeline(monkeypatch): + """Configure the pipeline at INFO with empty dedupe state for each test. + + Yields: + None. + """ + monkeypatch.delenv("REFLEX_LOG_JSON", raising=False) + monkeypatch.delenv("REFLEX_LOGLEVEL", raising=False) + monkeypatch.setattr(log, "_log_level", LogLevel.INFO) + log._dedupe_filter().seen.clear() + log.configure() + yield + monkeypatch.setattr(log, "_log_level", LogLevel.INFO) + log._dedupe_filter().seen.clear() + log.configure() + + +def test_rich_output_parity(capsys): + """Each level renders with the legacy prefix and stream.""" + log.set_log_level(LogLevel.DEBUG) + logger.debug("d") + logger.info("i") + logger.log(log.SUCCESS, "s") + logger.warning("w") + logger.error("e") + out, err = capsys.readouterr() + assert out == "Debug: d\nInfo: i\nSuccess: s\nWarning: w\n" + assert err == "e\n" + + +def test_markup_rendered_in_rich_mode(capsys): + """Rich markup in messages is rendered, not shown literally.""" + logger.info("hello [bold]world[/bold]") + out, _ = capsys.readouterr() + assert out == "Info: hello world\n" + + +def test_level_gating(capsys): + """Records below the configured level are dropped.""" + log.set_log_level(LogLevel.WARNING) + logger.info("hidden") + logger.warning("shown") + out, _ = capsys.readouterr() + assert out == "Warning: shown\n" + + +def test_default_level_gates_like_info(capsys): + """The DEFAULT log level shows info but not debug records.""" + log.set_log_level(LogLevel.DEFAULT) + logger.debug("hidden") + logger.info("shown") + out, _ = capsys.readouterr() + assert out == "Info: shown\n" + + +def test_dedupe(capsys): + """Records with dedupe set are only emitted once.""" + logger.info("once", extra={"dedupe": True}) + logger.info("once", extra={"dedupe": True}) + logger.info("twice") + logger.info("twice") + out, _ = capsys.readouterr() + assert out == "Info: once\nInfo: twice\nInfo: twice\n" + + +def test_json_mode(monkeypatch, capsys): + """JSON mode emits one parseable record per line with markup stripped.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + logger.info("hello [bold]world[/bold]") + logger.error("boom") + out, err = capsys.readouterr() + record = json.loads(out) + assert record["level"] == "info" + assert record["message"] == "hello world" + assert record["logger"] == logger.name + assert "timestamp" in record + assert "location" in record + assert "pid" in record + error_record = json.loads(err) + assert error_record["level"] == "error" + assert error_record["message"] == "boom" + + +def test_json_mode_success_level(monkeypatch, capsys): + """The custom SUCCESS level serializes with its own name.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + logger.log(log.SUCCESS, "done") + out, _ = capsys.readouterr() + assert json.loads(out)["level"] == "success" + + +def test_configure_idempotent(): + """Repeated configure calls never stack handlers.""" + log.configure() + log.configure() + for name in log.ROOT_LOGGER_NAMES: + root = logging.getLogger(name) + assert root.handlers.count(log._console_handler()) == 1 + assert log._json_handler() not in root.handlers + + +def test_configure_swaps_handler_in_json_mode(monkeypatch): + """Switching JSON mode swaps the sink instead of stacking it.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + root = logging.getLogger("reflex") + assert log._json_handler() in root.handlers + assert log._console_handler() not in root.handlers + + +def test_configure_removes_file_handler_when_full_logging_is_disabled(monkeypatch): + """Disabling full logging detaches its handler from every package logger.""" + handler = logging.NullHandler() + monkeypatch.setattr(log, "_file_handler", lambda: handler) + monkeypatch.setenv("REFLEX_ENABLE_FULL_LOGGING", "true") + try: + log.configure() + assert handler in logging.getLogger("reflex").handlers + + monkeypatch.setenv("REFLEX_ENABLE_FULL_LOGGING", "false") + log.configure() + assert all( + handler not in logging.getLogger(name).handlers + for name in log.ROOT_LOGGER_NAMES + ) + finally: + for name in log.ROOT_LOGGER_NAMES: + logger = logging.getLogger(name) + if handler in logger.handlers: + logger.removeHandler(handler) + + +def test_set_log_level_env_propagation(monkeypatch): + """Changing the level exports REFLEX_LOGLEVEL for subprocesses.""" + log.set_log_level(LogLevel.DEBUG) + import os + + assert os.environ.get("REFLEX_LOGLEVEL") == "debug" + assert log.get_log_level() is LogLevel.DEBUG + assert log.is_debug() + + +def test_set_log_level_rejects_strings(): + """Passing a raw string raises a TypeError.""" + with pytest.raises(TypeError): + log.set_log_level("debug") # pyright: ignore[reportArgumentType] + + +def test_set_log_level_none_is_noop(): + """Passing None keeps the current level.""" + log.set_log_level(None) + assert log.get_log_level() is LogLevel.INFO + + +def test_loglevel_total_ordering(): + """All comparison operators use enum position, not string order.""" + assert LogLevel.CRITICAL > LogLevel.DEBUG + assert LogLevel.DEBUG < LogLevel.DEFAULT < LogLevel.INFO + assert LogLevel.ERROR >= LogLevel.WARNING + assert LogLevel.DEBUG <= LogLevel.DEBUG + assert not LogLevel.CRITICAL < LogLevel.ERROR + + +def test_loglevel_to_logging_level(): + """LogLevel maps onto stdlib numeric levels.""" + assert LogLevel.DEBUG.to_logging_level() == logging.DEBUG + assert LogLevel.DEFAULT.to_logging_level() == logging.INFO + assert LogLevel.INFO.to_logging_level() == logging.INFO + assert LogLevel.WARNING.to_logging_level() == logging.WARNING + assert LogLevel.ERROR.to_logging_level() == logging.ERROR + assert LogLevel.CRITICAL.to_logging_level() == logging.CRITICAL + + +def test_strip_markup(): + """Markup tags are removed; malformed markup falls back to raw text.""" + assert log.strip_markup("no markup") == "no markup" + assert log.strip_markup("[bold]hi[/bold]") == "hi" + assert log.strip_markup("\\[literal]") == "[literal]" + assert log.strip_markup("[unclosed") == "[unclosed" + + +def test_deprecate_dedupes_and_renders(capsys): + """Deprecation warnings render once per feature and call site.""" + for _ in range(2): + log.deprecate( + feature_name="TestFeature", + reason="Use something else.", + deprecation_version="0.1.0", + removal_version="1.0", + ) + out, _ = capsys.readouterr() + assert out.count("DeprecationWarning: TestFeature has been deprecated") == 1 + assert "removed in 1.0" in out + + +def test_deprecate_json_extras(monkeypatch, capsys): + """Deprecations carry structured metadata in JSON mode.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + log.deprecate( + feature_name="JsonFeature", + reason="Use something else.", + deprecation_version="0.1.0", + removal_version="1.0", + ) + out, _ = capsys.readouterr() + record = json.loads(out) + assert record["feature_name"] == "JsonFeature" + assert record["deprecation_version"] == "0.1.0" + assert record["removal_version"] == "1.0" + assert record["kind"] == "deprecation" + + +def test_timing_logs_at_debug(capsys): + """The timing context manager emits a debug record with the duration.""" + log.set_log_level(LogLevel.DEBUG) + with log.timing(logger, "block"): + pass + out, _ = capsys.readouterr() + assert out.startswith("Debug: [timing] block: ") + + +def test_console_deprecate_preserves_rich_print_kwargs(monkeypatch): + """The legacy deprecation helper retains its Rich print contract.""" + rich_print = mock.Mock() + monkeypatch.setattr(console, "print", rich_print) + monkeypatch.setattr(console, "should_use_log_file_console", lambda: False) + monkeypatch.setattr( + console, "_get_first_non_framework_frame", lambda: None, raising=False + ) + + console.deprecate( + feature_name="OldFeature", + reason="Use NewFeature.", + deprecation_version="0.9.9", + removal_version="1.0", + dedupe=False, + markup=False, + ) + + rich_print.assert_called_once_with( + "[yellow]DeprecationWarning: OldFeature has been deprecated in version " + "0.9.9. Use NewFeature. It will be completely removed in 1.0.[/yellow]", + markup=False, + ) + + +def test_console_print_json_mode(monkeypatch, capsys): + """console.print stays machine-readable in JSON mode.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + console.print("plain [bold]message[/bold]") + out, _ = capsys.readouterr() + record = json.loads(out) + assert record["message"] == "plain message" + assert record["level"] == "info" + + +def test_console_rule_json_mode(monkeypatch, capsys): + """console.rule emits nothing in JSON mode.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + console.rule("Section") + out, _ = capsys.readouterr() + assert out == "" + + +def test_file_formatter_strips_markup_and_formats_timestamp(): + """The file formatter strips markup and supports the configured timestamp.""" + formatter = log._StripMarkupFormatter( + "[{asctime}] {levelname}: {message}", style="{" + ) + record = logging.LogRecord( + name="reflex.test", + level=logging.WARNING, + pathname=__file__, + lineno=1, + msg="[orange1]careful[/orange1]", + args=(), + exc_info=None, + ) + formatted = formatter.format(record) + assert formatted.endswith(" WARNING: careful") + assert formatted.startswith("[") + + +def test_log_file_path_honors_env(monkeypatch, tmp_path): + """REFLEX_LOG_FILE overrides the default log file location.""" + log_file = tmp_path / "my.log" + monkeypatch.setenv("REFLEX_LOG_FILE", str(log_file)) + assert log._log_file_path() == log_file + + +def test_every_logging_package_root_is_registered(): + """Workspace packages that log must appear in ROOT_LOGGER_NAMES. + + Loggers do not propagate across top-level package names, so a package + missing from the tuple silently escapes the pipeline. + """ + from pathlib import Path + + repo_root = Path(__file__).resolve().parents[4] + missing = { + src.name + for src in (repo_root / "packages").glob("*/src/*") + if src.is_dir() + and src.name not in log.ROOT_LOGGER_NAMES + and any( + "logging.getLogger(__name__)" in path.read_text(encoding="utf-8") + for path in src.rglob("*.py") + ) + } + assert not missing, ( + f"add {sorted(missing)} to reflex_base.utils.log.ROOT_LOGGER_NAMES so " + "their records go through the reflex logging pipeline" + ) + + +def test_bootstrap_defers_configure_until_first_record(monkeypatch, capsys): + """bootstrap() attaches sinks lazily and replays the triggering record.""" + monkeypatch.setattr(log, "_configured", False) + for name in log.ROOT_LOGGER_NAMES: + logging.getLogger(name).handlers.clear() + + log.bootstrap() + assert not log._configured + + logger.info("first record") + out, _ = capsys.readouterr() + assert out == "Info: first record\n" + assert log._configured + for name in log.ROOT_LOGGER_NAMES: + assert log._bootstrap_handler not in logging.getLogger(name).handlers diff --git a/tests/units/test_environment.py b/tests/units/test_environment.py index d3f93165957..f736b76eb28 100644 --- a/tests/units/test_environment.py +++ b/tests/units/test_environment.py @@ -1,6 +1,7 @@ """Tests for the environment module.""" import enum +import logging import os import tempfile from pathlib import Path @@ -543,19 +544,19 @@ def test_load_dotenv_from_files_with_dotenv(self, mock_load_dotenv): mock_load_dotenv.assert_any_call(file2, override=True) @patch("reflex_base.environment.load_dotenv", None) - @patch("reflex_base.utils.console") - def test_load_dotenv_from_files_without_dotenv(self, mock_console): + def test_load_dotenv_from_files_without_dotenv(self, caplog): """Test _load_dotenv_from_files when dotenv is not available. Args: - mock_console: Mock for the console object. + caplog: Pytest log capture fixture. """ with tempfile.TemporaryDirectory() as temp_dir: file1 = Path(temp_dir) / "file1.env" file1.touch() _load_dotenv_from_files([file1]) - mock_console.error.assert_called_once() + errors = [r for r in caplog.records if r.levelno == logging.ERROR] + assert len(errors) == 1 def test_load_dotenv_from_files_empty_list(self): """Test _load_dotenv_from_files with empty file list.""" From a7b5e04e3b8f9c7e46162548e099c08e042bec13 Mon Sep 17 00:00:00 2001 From: Farhan Date: Wed, 12 Aug 2026 01:28:57 +0500 Subject: [PATCH 02/11] refactor(log): single reflex root logger, CLI-only handlers, opt-in markup Address review feedback on the logging pipeline: - Parent every package logger (reflex_base, reflex_cli, reflex_components_*) under the top-level "reflex" logger, so all reflex logging is tunable in one place (or per package) with standard stdlib APIs. Propagation stays enabled in library mode. - Attach handlers only in managed mode, i.e. under the reflex CLI or a worker it spawned (REFLEX_MANAGED_LOGGING marker inherited through the environment). A plain "import reflex" no longer touches handlers or propagation; records flow to the root logger for the application to handle. Managed mode cuts propagation so an app-side basicConfig cannot double-emit records or break the --json output contract. This also removes the _BootstrapHandler lazy-attach trick. - Rich markup in log messages is now opt-in via extra={"rich": True}; plain records keep their literal brackets in every sink instead of being markup-stripped. - The dedupe filter stores key hashes instead of full messages. - Drop the autouse conftest fixture that re-attached caplog to each package root; propagation makes pytest capture work natively. --- .../reflex-base/src/reflex_base/utils/log.py | 188 +++++++++++------- reflex/__init__.py | 7 +- tests/units/conftest.py | 20 -- tests/units/reflex_base/utils/test_log.py | 179 ++++++++++++----- 4 files changed, 250 insertions(+), 144 deletions(-) diff --git a/packages/reflex-base/src/reflex_base/utils/log.py b/packages/reflex-base/src/reflex_base/utils/log.py index 7bd172a1e6f..90470b1c321 100644 --- a/packages/reflex-base/src/reflex_base/utils/log.py +++ b/packages/reflex-base/src/reflex_base/utils/log.py @@ -1,10 +1,19 @@ """Standard-library logging pipeline with rich rendering and JSON output. Reflex modules log through plain ``logging.getLogger(__name__)`` loggers. -This module owns the sinks: a rich-rendering console handler (colored, same +At import time :func:`bootstrap` parents every workspace package logger +(``reflex_base``, ``reflex_cli``, ``reflex_components_*``) under the single +``reflex`` logger, so downstream code tunes all reflex logging in one place +(``logging.getLogger("reflex")``) or per package, with standard stdlib APIs. + +Handlers attach only in *managed* mode, i.e. when running under the reflex +CLI (or one of its worker subprocesses, which inherit the marker through the +environment). The sinks are: a rich-rendering console handler (colored, same look as the legacy ``console`` helpers), a JSON-lines handler for machine consumption (``REFLEX_LOG_JSON`` / ``--json``), and an optional file handler -(``REFLEX_ENABLE_FULL_LOGGING`` / ``REFLEX_LOG_FILE``). +(``REFLEX_ENABLE_FULL_LOGGING`` / ``REFLEX_LOG_FILE``). Outside the CLI no +handler is attached at all: records propagate to the root logger and the +application's own logging configuration (or ``logging.lastResort``) applies. """ from __future__ import annotations @@ -37,12 +46,11 @@ SUCCESS = 25 logging.addLevelName(SUCCESS, "SUCCESS") -# Package-root loggers that receive the reflex handlers. Every distribution -# that logs needs its root here: loggers do not propagate across the -# ``reflex_*`` top-level names, so an omitted root escapes the pipeline -# entirely (no styling, no level gating, no JSON records, no file capture). -ROOT_LOGGER_NAMES = ( - "reflex", +# Package-root loggers reparented under the top-level ``reflex`` logger. +# Every distribution that logs needs its root here: loggers do not propagate +# across the ``reflex_*`` top-level names, so an omitted root escapes the +# hierarchy entirely (no level gating, no reflex sinks, no file capture). +PACKAGE_LOGGER_NAMES = ( "reflex_base", "reflex_cli", "reflex_components_core", @@ -52,6 +60,13 @@ "reflex_components_react_player", ) +# The single logger the reflex sinks attach to; parent of every package logger. +_REFLEX_LOGGER = logging.getLogger("reflex") + +# Marker inherited by worker subprocesses: handlers attach only when running +# under the reflex CLI. Read with os.environ so bootstrap stays import-light. +_MANAGED_ENV_VAR = "REFLEX_MANAGED_LOGGING" + # Consoles for pretty printing (shared with reflex_base.utils.console). _console = Console(highlight=False) _console_stderr = Console(stderr=True, highlight=False) @@ -132,7 +147,9 @@ class DedupeFilter(logging.Filter): def __init__(self): """Initialize the filter with an empty seen-set.""" super().__init__() - self.seen: set = set() + # Hashes only, so deduped messages are not retained for the process + # lifetime. + self.seen: set[int] = set() def register(self, key: Hashable) -> bool: """Record a dedupe key, reporting whether it is new. @@ -143,9 +160,10 @@ def register(self, key: Hashable) -> bool: Returns: True the first time the key is seen, False afterwards. """ - if key in self.seen: + hashed = hash(key) + if hashed in self.seen: return False - self.seen.add(key) + self.seen.add(hashed) return True def filter(self, record: logging.LogRecord) -> bool: @@ -183,7 +201,12 @@ def emit(self, record: logging.LogRecord): if progress is not None: console = progress.console end = getattr(record, "end", "\n") - console.print(f"{prefix}{record.getMessage()}", style=style, end=end) + # Markup is opt-in per record (``extra={"rich": True}``); plain + # messages keep their literal brackets. + markup = bool(getattr(record, "rich", False)) + console.print( + f"{prefix}{record.getMessage()}", style=style, end=end, markup=markup + ) if record.exc_info and record.exc_info[0] is not None: # Tracebacks may contain user data; never parse them as markup. console.print(self.format_exception(record), style=style, markup=False) @@ -231,13 +254,16 @@ def emit(self, record: logging.LogRecord): record: The log record. """ try: + message = record.getMessage() + if getattr(record, "rich", False): + message = strip_markup(message) payload = { "timestamp": datetime.datetime.fromtimestamp( record.created, tz=datetime.timezone.utc ).isoformat(), "level": logging.getLevelName(record.levelno).lower(), "logger": record.name, - "message": strip_markup(record.getMessage()), + "message": message, "location": f"{record.pathname}:{record.lineno}", "pid": record.process, } @@ -254,11 +280,11 @@ def emit(self, record: logging.LogRecord): self.handleError(record) -class _StripMarkupFormatter(logging.Formatter): - """Formatter that removes rich markup from messages.""" +class _FileFormatter(logging.Formatter): + """Formatter that removes rich markup from markup-enabled messages.""" def format(self, record: logging.LogRecord) -> str: - """Format a record with markup stripped. + """Format a record, stripping markup from records that opted into it. Args: record: The log record. @@ -266,6 +292,8 @@ def format(self, record: logging.LogRecord) -> str: Returns: The formatted line. """ + if not getattr(record, "rich", False): + return super().format(record) msg, args = record.msg, record.args try: record.msg = strip_markup(record.getMessage()) @@ -301,7 +329,7 @@ def _file_handler() -> logging.FileHandler: """ handler = logging.FileHandler(_log_file_path(), mode="w", encoding="utf-8") handler.setFormatter( - _StripMarkupFormatter("[{asctime}] {levelname}: {message}", style="{") + _FileFormatter("[{asctime}] {levelname}: {message}", style="{") ) return handler @@ -355,7 +383,7 @@ def set_json_mode(enabled: bool): """Enable or disable machine-readable JSON log output. Sets the environment variable so subprocesses inherit the mode, then - re-attaches the sinks. + re-attaches the sinks (in managed mode; outside the CLI no sink exists). Args: enabled: Whether to emit JSON records. @@ -363,7 +391,8 @@ def set_json_mode(enabled: bool): from reflex_base.environment import environment environment.REFLEX_LOG_JSON.set(enabled) - configure() + if is_managed_mode(): + configure() def dedupe_once(key: Hashable) -> bool: @@ -408,53 +437,53 @@ def emit_json_print(msg: str, *, dedupe: bool = False, stderr: bool = False): _active_file_handler: logging.FileHandler | None = None -class _BootstrapHandler(logging.Handler): - """Attach the real sinks on the first record, then replay it through them.""" - - def handle(self, record: logging.LogRecord) -> bool: - """Configure the pipeline and hand the record to the real sinks. +def is_managed_mode() -> bool: + """Check whether this process runs under the reflex CLI. - Args: - record: The log record. + Returns: + True if the reflex CLI (or a worker it spawned) owns log rendering. + """ + return os.environ.get(_MANAGED_ENV_VAR) == "true" - Returns: - True, matching the Handler.handle contract. - """ - if _configured: - # configure() detaches this handler, so reaching here means it - # failed to do so. Drop the record rather than recurse. - return True - configure() - logging.getLogger(record.name).handle(record) - return True +def enable_managed_logging(): + """Mark this process (and its subprocesses) as CLI-managed and attach sinks. -_bootstrap_handler = _BootstrapHandler() + Called from the reflex CLI entry point. Worker subprocesses inherit the + marker through the environment and configure themselves in bootstrap(). + """ + os.environ[_MANAGED_ENV_VAR] = "true" + configure() def bootstrap(): - """Claim the reflex loggers without importing the environment machinery. - - ``configure`` needs :mod:`reflex_base.environment`, which drags in the - config and plugin stack (and with it pandas and plotly). Importing that at - ``import reflex`` time would defeat the package's lazy loading, so the - sinks are attached on the first record instead. The permissive logger level - keeps records that a later ``configure`` may want; the sink's own level - does the real gating. + """Parent the package loggers under the top-level ``reflex`` logger. + + Called at ``import reflex`` time, so it must stay import-light (no + :mod:`reflex_base.environment`). The manual parent assignment is permanent: + the logging manager only fixes up parents when it creates a logger, and + loggers created later under a package root chain to the existing root. + In managed mode (marker inherited from the CLI) the sinks attach + immediately so worker records render from the first line. """ - for name in ROOT_LOGGER_NAMES: - logger = logging.getLogger(name) - logger.propagate = False - logger.setLevel(logging.DEBUG) - logger.addHandler(_bootstrap_handler) + for name in PACKAGE_LOGGER_NAMES: + child = logging.getLogger(name) + child.parent = _REFLEX_LOGGER + child.propagate = True + # Inherit the effective level from "reflex"; setLevel also clears the + # isEnabledFor caches, which reparenting alone does not. + child.setLevel(logging.NOTSET) + if is_managed_mode(): + configure() def configure(): - """Attach the reflex handlers to the reflex package-root loggers. + """Attach the reflex sinks to the top-level ``reflex`` logger. Idempotent: handler instances are cached and re-attached, never stacked. - Only reflex-owned loggers are touched (propagation to the root logger is - disabled), so a user application's own logging setup is unaffected. + Propagation to the root logger is cut while the sinks are attached, so an + application-side ``basicConfig`` cannot double-emit reflex records or + break the ``--json`` only-JSON output contract. """ global _active_file_handler, _configured from reflex_base.environment import environment @@ -470,30 +499,43 @@ def configure(): file_handler = _active_file_handler if full_logging: file_handler = _active_file_handler = _file_handler() - logger_level = logging.DEBUG if full_logging else _log_level.to_logging_level() # addHandler/removeHandler are no-ops when the handler is already in the # desired state, so no membership checks are needed here. - for name in ROOT_LOGGER_NAMES: - logger = logging.getLogger(name) - logger.propagate = False - logger.setLevel(logger_level) - logger.removeHandler(_bootstrap_handler) - logger.removeHandler(other) - logger.addHandler(sink) - if file_handler is not None: - if full_logging: - logger.addHandler(file_handler) - else: - logger.removeHandler(file_handler) + _REFLEX_LOGGER.propagate = False + _REFLEX_LOGGER.setLevel( + logging.DEBUG if full_logging else _log_level.to_logging_level() + ) + _REFLEX_LOGGER.removeHandler(other) + _REFLEX_LOGGER.addHandler(sink) + if file_handler is not None: + if full_logging: + _REFLEX_LOGGER.addHandler(file_handler) + else: + _REFLEX_LOGGER.removeHandler(file_handler) _configured = True def ensure_configured(): - """Configure the logging pipeline if it has not been configured yet.""" - if not _configured: + """Attach the sinks in managed mode if that has not happened yet. + + Outside the CLI this is a no-op: no handler is attached and records + propagate to the root logger for the application to handle. + """ + if not _configured and is_managed_mode(): configure() +def _reset(): + """Detach the sinks and restore propagation (test teardown helper).""" + global _configured + for handler in (_console_handler(), _json_handler(), _active_file_handler): + if handler is not None: + _REFLEX_LOGGER.removeHandler(handler) + _REFLEX_LOGGER.propagate = True + _REFLEX_LOGGER.setLevel(logging.NOTSET) + _configured = False + + def set_log_level(log_level: LogLevel | None): """Set the log level. @@ -513,7 +555,12 @@ def set_log_level(log_level: LogLevel | None): # Set the loglevel persistently for subprocesses. os.environ["REFLEX_LOGLEVEL"] = log_level.value _log_level = log_level - configure() + if is_managed_mode(): + configure() + else: + # Library mode: adjust the level like any stdlib API would, but never + # attach handlers behind the application's back. + _REFLEX_LOGGER.setLevel(log_level.to_logging_level()) def get_log_level() -> LogLevel: @@ -549,7 +596,7 @@ def timing(logger: logging.Logger, msg: str) -> Iterator[None]: try: yield finally: - logger.debug("[white]\\[timing] %s: %.2fs[/white]", msg, time.time() - start) + logger.debug("[timing] %s: %.2fs", msg, time.time() - start) @once @@ -663,7 +710,6 @@ def deprecate( if dedupe and not dedupe_once(f"deprecation:{dedupe_key}"): return - ensure_configured() msg = ( f"{feature_name} has been deprecated in version {deprecation_version}. {reason.rstrip('.').lstrip('. ')}. It will be completely " f"removed in {removal_version}.{loc}" diff --git a/reflex/__init__.py b/reflex/__init__.py index b6d53cac6a0..66b77205ae2 100644 --- a/reflex/__init__.py +++ b/reflex/__init__.py @@ -89,9 +89,10 @@ from reflex_base.utils import lazy_loader from reflex_base.utils import log as _log -# Claim the reflex loggers so records render styled even before any config is -# loaded (only reflex-owned loggers are touched). The sinks themselves attach -# on the first record, keeping this import cheap. +# Parent the workspace package loggers under the single "reflex" logger so +# all reflex logging is tunable in one place. Sinks attach only when the +# reflex CLI manages this process, keeping this import cheap and leaving +# library users' logging configuration untouched. _log.bootstrap() del _log diff --git a/tests/units/conftest.py b/tests/units/conftest.py index 6b5ea66705d..8ef4232fbc7 100644 --- a/tests/units/conftest.py +++ b/tests/units/conftest.py @@ -1,6 +1,5 @@ """Test fixtures.""" -import logging import platform import traceback import uuid @@ -15,7 +14,6 @@ from reflex_base.event.context import EventContext from reflex_base.event.processor import BaseStateEventProcessor, EventProcessor from reflex_base.registry import RegistrationContext -from reflex_base.utils import log from reflex.app import App from reflex.istate.manager import StateManager @@ -47,24 +45,6 @@ def _isolate_app_in_context() -> Generator[None, None, None]: object.__setattr__(ctx, "_app", None) -@pytest.fixture(autouse=True) -def _capture_reflex_logs(caplog): - """Attach pytest's capture handler to Reflex package loggers. - - The logging pipeline deliberately disables propagation at package roots, - while pytest normally captures records from the process root logger. - - Yields: - None. - """ - loggers = [logging.getLogger(name) for name in log.ROOT_LOGGER_NAMES] - for logger in loggers: - logger.addHandler(caplog.handler) - yield - for logger in loggers: - logger.removeHandler(caplog.handler) - - @pytest.fixture def app() -> App: """A base app. diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index a2e48f1f303..947fd51bb70 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -13,20 +13,30 @@ @pytest.fixture(autouse=True) def clean_pipeline(monkeypatch): - """Configure the pipeline at INFO with empty dedupe state for each test. + """Configure the managed pipeline at INFO with empty dedupe state. + + Restores library mode (no sinks, propagation on) after each test so the + rest of the unit suite keeps standard root-logger capture. Yields: None. """ monkeypatch.delenv("REFLEX_LOG_JSON", raising=False) monkeypatch.delenv("REFLEX_LOGLEVEL", raising=False) + monkeypatch.setenv(log._MANAGED_ENV_VAR, "true") monkeypatch.setattr(log, "_log_level", LogLevel.INFO) log._dedupe_filter().seen.clear() log.configure() yield - monkeypatch.setattr(log, "_log_level", LogLevel.INFO) log._dedupe_filter().seen.clear() - log.configure() + log._reset() + + +@pytest.fixture +def library_mode(monkeypatch): + """Drop into library mode: no managed marker, no sinks attached.""" + monkeypatch.delenv(log._MANAGED_ENV_VAR, raising=False) + log._reset() def test_rich_output_parity(capsys): @@ -42,13 +52,20 @@ def test_rich_output_parity(capsys): assert err == "e\n" -def test_markup_rendered_in_rich_mode(capsys): - """Rich markup in messages is rendered, not shown literally.""" - logger.info("hello [bold]world[/bold]") +def test_markup_rendered_when_opted_in(capsys): + """Records carrying ``rich=True`` render their markup.""" + logger.info("hello [bold]world[/bold]", extra={"rich": True}) out, _ = capsys.readouterr() assert out == "Info: hello world\n" +def test_markup_literal_by_default(capsys): + """Without the opt-in, bracketed text renders literally.""" + logger.info("AssertionErr: foo[bar] != 'baz'") + out, _ = capsys.readouterr() + assert out == "Info: AssertionErr: foo[bar] != 'baz'\n" + + def test_level_gating(capsys): """Records below the configured level are dropped.""" log.set_log_level(LogLevel.WARNING) @@ -77,11 +94,19 @@ def test_dedupe(capsys): assert out == "Info: once\nInfo: twice\nInfo: twice\n" +def test_dedupe_filter_stores_hashes_not_messages(): + """The seen-set retains hashes only, never the deduped messages.""" + logger.info("sensitive message contents", extra={"dedupe": True}) + seen = log._dedupe_filter().seen + assert seen + assert all(isinstance(entry, int) for entry in seen) + + def test_json_mode(monkeypatch, capsys): - """JSON mode emits one parseable record per line with markup stripped.""" + """JSON mode emits one parseable record per line.""" monkeypatch.setenv("REFLEX_LOG_JSON", "true") log.configure() - logger.info("hello [bold]world[/bold]") + logger.info("hello [bold]world[/bold]", extra={"rich": True}) logger.error("boom") out, err = capsys.readouterr() record = json.loads(out) @@ -96,6 +121,15 @@ def test_json_mode(monkeypatch, capsys): assert error_record["message"] == "boom" +def test_json_mode_preserves_brackets_in_plain_records(monkeypatch, capsys): + """Only ``rich=True`` records are markup-stripped in JSON output.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + logger.info("foo[bar]") + out, _ = capsys.readouterr() + assert json.loads(out)["message"] == "foo[bar]" + + def test_json_mode_success_level(monkeypatch, capsys): """The custom SUCCESS level serializes with its own name.""" monkeypatch.setenv("REFLEX_LOG_JSON", "true") @@ -109,23 +143,38 @@ def test_configure_idempotent(): """Repeated configure calls never stack handlers.""" log.configure() log.configure() - for name in log.ROOT_LOGGER_NAMES: - root = logging.getLogger(name) - assert root.handlers.count(log._console_handler()) == 1 - assert log._json_handler() not in root.handlers + reflex_logger = logging.getLogger("reflex") + assert reflex_logger.handlers.count(log._console_handler()) == 1 + assert log._json_handler() not in reflex_logger.handlers + assert all( + not logging.getLogger(name).handlers for name in log.PACKAGE_LOGGER_NAMES + ) def test_configure_swaps_handler_in_json_mode(monkeypatch): """Switching JSON mode swaps the sink instead of stacking it.""" monkeypatch.setenv("REFLEX_LOG_JSON", "true") log.configure() - root = logging.getLogger("reflex") - assert log._json_handler() in root.handlers - assert log._console_handler() not in root.handlers + reflex_logger = logging.getLogger("reflex") + assert log._json_handler() in reflex_logger.handlers + assert log._console_handler() not in reflex_logger.handlers + + +def test_configure_cuts_propagation_to_root(): + """Managed mode owns the terminal: records never reach root handlers.""" + root_sink = mock.Mock(spec=logging.Handler) + root_sink.level = logging.DEBUG + logging.getLogger().addHandler(root_sink) + try: + assert logging.getLogger("reflex").propagate is False + logger.warning("managed") + root_sink.handle.assert_not_called() + finally: + logging.getLogger().removeHandler(root_sink) def test_configure_removes_file_handler_when_full_logging_is_disabled(monkeypatch): - """Disabling full logging detaches its handler from every package logger.""" + """Disabling full logging detaches its handler again.""" handler = logging.NullHandler() monkeypatch.setattr(log, "_file_handler", lambda: handler) monkeypatch.setenv("REFLEX_ENABLE_FULL_LOGGING", "true") @@ -135,22 +184,17 @@ def test_configure_removes_file_handler_when_full_logging_is_disabled(monkeypatc monkeypatch.setenv("REFLEX_ENABLE_FULL_LOGGING", "false") log.configure() - assert all( - handler not in logging.getLogger(name).handlers - for name in log.ROOT_LOGGER_NAMES - ) + assert handler not in logging.getLogger("reflex").handlers finally: - for name in log.ROOT_LOGGER_NAMES: - logger = logging.getLogger(name) - if handler in logger.handlers: - logger.removeHandler(handler) + logging.getLogger("reflex").removeHandler(handler) def test_set_log_level_env_propagation(monkeypatch): """Changing the level exports REFLEX_LOGLEVEL for subprocesses.""" - log.set_log_level(LogLevel.DEBUG) import os + monkeypatch.delenv("REFLEX_LOGLEVEL", raising=False) + log.set_log_level(LogLevel.DEBUG) assert os.environ.get("REFLEX_LOGLEVEL") == "debug" assert log.get_log_level() is LogLevel.DEBUG assert log.is_debug() @@ -168,6 +212,15 @@ def test_set_log_level_none_is_noop(): assert log.get_log_level() is LogLevel.INFO +def test_set_log_level_in_library_mode_attaches_nothing(library_mode): + """Library-mode level tuning adjusts the logger but never adds sinks.""" + log.set_log_level(LogLevel.DEBUG) + reflex_logger = logging.getLogger("reflex") + assert reflex_logger.level == logging.DEBUG + assert reflex_logger.handlers == [] + assert reflex_logger.propagate is True + + def test_loglevel_total_ordering(): """All comparison operators use enum position, not string order.""" assert LogLevel.CRITICAL > LogLevel.DEBUG @@ -279,23 +332,28 @@ def test_console_rule_json_mode(monkeypatch, capsys): assert out == "" -def test_file_formatter_strips_markup_and_formats_timestamp(): - """The file formatter strips markup and supports the configured timestamp.""" - formatter = log._StripMarkupFormatter( - "[{asctime}] {levelname}: {message}", style="{" - ) +def _file_record(msg: str, *, rich: bool = False) -> logging.LogRecord: record = logging.LogRecord( name="reflex.test", level=logging.WARNING, pathname=__file__, lineno=1, - msg="[orange1]careful[/orange1]", + msg=msg, args=(), exc_info=None, ) - formatted = formatter.format(record) + if rich: + record.rich = True + return record + + +def test_file_formatter_strips_markup_only_when_opted_in(): + """The file formatter strips markup from rich records and no others.""" + formatter = log._FileFormatter("[{asctime}] {levelname}: {message}", style="{") + formatted = formatter.format(_file_record("[orange1]careful[/orange1]", rich=True)) assert formatted.endswith(" WARNING: careful") assert formatted.startswith("[") + assert formatter.format(_file_record("foo[bar]")).endswith(" WARNING: foo[bar]") def test_log_file_path_honors_env(monkeypatch, tmp_path): @@ -306,10 +364,10 @@ def test_log_file_path_honors_env(monkeypatch, tmp_path): def test_every_logging_package_root_is_registered(): - """Workspace packages that log must appear in ROOT_LOGGER_NAMES. + """Workspace packages that log must appear in PACKAGE_LOGGER_NAMES. Loggers do not propagate across top-level package names, so a package - missing from the tuple silently escapes the pipeline. + missing from the tuple silently escapes the reflex logger hierarchy. """ from pathlib import Path @@ -318,30 +376,51 @@ def test_every_logging_package_root_is_registered(): src.name for src in (repo_root / "packages").glob("*/src/*") if src.is_dir() - and src.name not in log.ROOT_LOGGER_NAMES + and src.name not in log.PACKAGE_LOGGER_NAMES and any( "logging.getLogger(__name__)" in path.read_text(encoding="utf-8") for path in src.rglob("*.py") ) } assert not missing, ( - f"add {sorted(missing)} to reflex_base.utils.log.ROOT_LOGGER_NAMES so " - "their records go through the reflex logging pipeline" + f"add {sorted(missing)} to reflex_base.utils.log.PACKAGE_LOGGER_NAMES so " + "their records join the reflex logger hierarchy" ) -def test_bootstrap_defers_configure_until_first_record(monkeypatch, capsys): - """bootstrap() attaches sinks lazily and replays the triggering record.""" - monkeypatch.setattr(log, "_configured", False) - for name in log.ROOT_LOGGER_NAMES: - logging.getLogger(name).handlers.clear() - +def test_bootstrap_parents_package_loggers_under_reflex(library_mode): + """Every package logger chains to root through the ``reflex`` logger.""" + log.bootstrap() + reflex_logger = logging.getLogger("reflex") + assert reflex_logger.handlers == [] + assert reflex_logger.propagate is True + for name in log.PACKAGE_LOGGER_NAMES: + package_logger = logging.getLogger(name) + assert package_logger.parent is reflex_logger + assert package_logger.propagate is True + assert package_logger.level == logging.NOTSET + # Loggers created after bootstrap join the chain through their package root. + deep = logging.getLogger("reflex_base.brand.new_child") + parents = [] + node = deep + while node := node.parent: + parents.append(node) + assert reflex_logger in parents + assert parents[-1] is logging.getLogger() + + +def test_bootstrap_configures_when_managed(monkeypatch): + """Workers inherit the CLI marker and attach sinks at import time.""" + monkeypatch.setenv(log._MANAGED_ENV_VAR, "true") + log._reset() log.bootstrap() - assert not log._configured - - logger.info("first record") - out, _ = capsys.readouterr() - assert out == "Info: first record\n" assert log._configured - for name in log.ROOT_LOGGER_NAMES: - assert log._bootstrap_handler not in logging.getLogger(name).handlers + assert log._console_handler() in logging.getLogger("reflex").handlers + + +def test_library_mode_records_propagate_to_root(library_mode, caplog): + """Without the CLI, records reach root for the app (and pytest) to capture.""" + log.bootstrap() + with caplog.at_level(logging.INFO, logger="reflex"): + logger.info("through the root") + assert "through the root" in caplog.text From 89652f1ecef797aa0b7b9754265dbe4a72e1e82b Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 17 Aug 2026 22:28:54 +0000 Subject: [PATCH 03/11] fix(log): review fixes for the logging pipeline - share one full-logging file between the pipeline handler and the legacy console writer, instead of opening (and unlinking) two files - create the parent directory of a configured REFLEX_LOG_FILE path - keep the originating severity in JSON records emitted by the legacy console helpers, and route console.log/print_table/PoorProgress through JSON mode instead of writing rich text into the machine-readable stream - keep an application's own level configuration on the package loggers when bootstrap reparents them - drop the duplicate console._LOG_LEVEL state; the log module's level is the single source of truth --- .../src/reflex_base/utils/console.py | 78 ++++++++-------- .../reflex-base/src/reflex_base/utils/log.py | 44 ++++++--- reflex/utils/exec.py | 2 +- reflex/utils/export.py | 4 +- tests/units/reflex_base/utils/test_log.py | 93 +++++++++++++++++++ tests/units/utils/test_utils.py | 2 +- 6 files changed, 170 insertions(+), 53 deletions(-) diff --git a/packages/reflex-base/src/reflex_base/utils/console.py b/packages/reflex-base/src/reflex_base/utils/console.py index 0fe9c80ebcd..7051d275030 100644 --- a/packages/reflex-base/src/reflex_base/utils/console.py +++ b/packages/reflex-base/src/reflex_base/utils/console.py @@ -19,7 +19,6 @@ from rich.table import Table from reflex_base.constants import LogLevel -from reflex_base.constants.base import Reflex from reflex_base.utils import log as _log from reflex_base.utils.decorator import once @@ -27,9 +26,6 @@ _console = Console(highlight=False) _console_stderr = Console(stderr=True, highlight=False) -# The current log level. -_LOG_LEVEL = LogLevel.INFO - # Deprecated features who's warning has been printed. _EMITTED_DEPRECATION_WARNINGS = set() @@ -61,11 +57,7 @@ def set_log_level(log_level: LogLevel | None): Args: log_level: The log level to set. """ - if log_level is None: - return _log.set_log_level(log_level) - global _LOG_LEVEL - _LOG_LEVEL = log_level def is_debug() -> bool: @@ -74,19 +66,20 @@ def is_debug() -> bool: Returns: True if the log level is debug. """ - return _LOG_LEVEL <= LogLevel.DEBUG + return _log.is_debug() -def print(msg: str, *, dedupe: bool = False, **kwargs): +def print(msg: str, *, dedupe: bool = False, level: str = "info", **kwargs): """Print a message. Args: msg: The message to print. dedupe: If True, suppress multiple console logs of print message. + level: The severity reported in JSON mode. kwargs: Keyword arguments to pass to the print function. """ if _log.is_json_mode(): - _log.emit_json_print(msg, dedupe=dedupe) + _log.emit_json_print(msg, level=level, dedupe=dedupe) return if dedupe: if msg in _EMITTED_PRINTS: @@ -95,16 +88,17 @@ def print(msg: str, *, dedupe: bool = False, **kwargs): _console.print(msg, **kwargs) -def _print_stderr(msg: str, *, dedupe: bool = False, **kwargs): +def _print_stderr(msg: str, *, dedupe: bool = False, level: str = "error", **kwargs): """Print a message to stderr. Args: msg: The message to print. dedupe: If True, suppress multiple console logs of print message. + level: The severity reported in JSON mode. kwargs: Keyword arguments to pass to the print function. """ if _log.is_json_mode(): - _log.emit_json_print(msg, dedupe=dedupe, stderr=True) + _log.emit_json_print(msg, level=level, dedupe=dedupe, stderr=True) return if dedupe: if msg in _EMITTED_PRINTS: @@ -117,22 +111,13 @@ def _print_stderr(msg: str, *, dedupe: bool = False, **kwargs): def log_file_console(): """Create a console that logs to a file. + Writes through the stream of the logging pipeline's file handler, so the + legacy helpers and the ``logging`` sinks share one full-logging file. + Returns: A Console object that logs to a file. """ - from reflex_base.environment import environment - - if not (env_log_file := environment.REFLEX_LOG_FILE.get()): - subseconds = int((time.time() % 1) * 1000) - timestamp = time.strftime("%Y-%m-%d_%H-%M-%S") + f"_{subseconds:03d}" - log_file = Reflex.DIR / "logs" / (timestamp + ".log") - log_file.parent.mkdir(parents=True, exist_ok=True) - else: - log_file = env_log_file - if log_file.exists(): - log_file.unlink() - log_file.touch() - return Console(file=log_file.open("a", encoding="utf-8")) + return Console(file=_log.log_file_stream()) @once @@ -175,7 +160,7 @@ def debug(msg: str, *, dedupe: bool = False, **kwargs): if progress := kwargs.pop("progress", None): progress.console.print(msg_, **kwargs) else: - print(msg_, **kwargs) + print(msg_, level="debug", **kwargs) if should_use_log_file_console() and kwargs.pop("progress", None) is None: print_to_log_file(f"[purple]Debug: {msg}[/purple]", **kwargs) @@ -188,7 +173,7 @@ def info(msg: str, *, dedupe: bool = False, **kwargs): dedupe: If True, suppress multiple console logs of info message. kwargs: Keyword arguments to pass to the print function. """ - if _LOG_LEVEL <= LogLevel.INFO: + if _log.get_log_level() <= LogLevel.INFO: if dedupe: if msg in _EMITTED_INFO: return @@ -206,12 +191,12 @@ def success(msg: str, *, dedupe: bool = False, **kwargs): dedupe: If True, suppress multiple console logs of success message. kwargs: Keyword arguments to pass to the print function. """ - if _LOG_LEVEL <= LogLevel.INFO: + if _log.get_log_level() <= LogLevel.INFO: if dedupe: if msg in _EMITTED_SUCCESS: return _EMITTED_SUCCESS.add(msg) - print(f"[green]Success: {msg}[/green]", **kwargs) + print(f"[green]Success: {msg}[/green]", level="success", **kwargs) if should_use_log_file_console(): print_to_log_file(f"[green]Success: {msg}[/green]", **kwargs) @@ -224,12 +209,15 @@ def log(msg: str, *, dedupe: bool = False, **kwargs): dedupe: If True, suppress multiple console logs of log message. kwargs: Keyword arguments to pass to the print function. """ - if _LOG_LEVEL <= LogLevel.INFO: + if _log.get_log_level() <= LogLevel.INFO: if dedupe: if msg in _EMITTED_LOGS: return _EMITTED_LOGS.add(msg) - _console.log(msg, **kwargs) + if _log.is_json_mode(): + _log.emit_json_print(msg) + else: + _console.log(msg, **kwargs) if should_use_log_file_console(): print_to_log_file(msg, **kwargs) @@ -254,12 +242,12 @@ def warn(msg: str, *, dedupe: bool = False, **kwargs): dedupe: If True, suppress multiple console logs of warning message. kwargs: Keyword arguments to pass to the print function. """ - if _LOG_LEVEL <= LogLevel.WARNING: + if _log.get_log_level() <= LogLevel.WARNING: if dedupe: if msg in _EMITTED_WARNINGS: return _EMITTED_WARNINGS.add(msg) - print(f"[orange1]Warning: {msg}[/orange1]", **kwargs) + print(f"[orange1]Warning: {msg}[/orange1]", level="warning", **kwargs) if should_use_log_file_console(): print_to_log_file(f"[orange1]Warning: {msg}[/orange1]", **kwargs) @@ -370,8 +358,12 @@ def deprecate( f"{feature_name} has been deprecated in version {deprecation_version}. {reason.rstrip('.').lstrip('. ')}. It will be completely " f"removed in {removal_version}.{loc}" ) - if _LOG_LEVEL <= LogLevel.WARNING: - print(f"[yellow]DeprecationWarning: {msg}[/yellow]", **kwargs) + if _log.get_log_level() <= LogLevel.WARNING: + print( + f"[yellow]DeprecationWarning: {msg}[/yellow]", + level="warning", + **kwargs, + ) if should_use_log_file_console(): print_to_log_file(f"[yellow]DeprecationWarning: {msg}[/yellow]", **kwargs) if dedupe: @@ -386,7 +378,7 @@ def error(msg: str, *, dedupe: bool = False, **kwargs): dedupe: If True, suppress multiple console logs of error message. kwargs: Keyword arguments to pass to the print function. """ - if _LOG_LEVEL <= LogLevel.ERROR: + if _log.get_log_level() <= LogLevel.ERROR: if dedupe: if msg in _EMITTED_ERRORS: return @@ -429,6 +421,14 @@ def print_table( tabular_data: The data to print in tabular format. headers: The headers for the table. """ + if _log.is_json_mode(): + # A table is requested output, not decoration: keep the rows in the + # machine-readable stream instead of rendering Rich text into it. + _log.emit_json_print( + "", + table={"headers": list(headers), "rows": tabular_data}, + ) + return table = Table() for column in headers: @@ -521,7 +521,9 @@ def advance(self, task: TaskID, advance: int = 1): if task in self.tasks: self.tasks[task]["current"] += advance self.progress += advance - _console.print(f"Progress: {self.progress}/{self.total}") + # Through console.print, so JSON mode gets a record instead of a + # plain line in the machine-readable stream. + print(f"Progress: {self.progress}/{self.total}") def update(self, task: TaskID, total: int | None = None): """Update properties of a task. diff --git a/packages/reflex-base/src/reflex_base/utils/log.py b/packages/reflex-base/src/reflex_base/utils/log.py index 90470b1c321..e4614ee9aba 100644 --- a/packages/reflex-base/src/reflex_base/utils/log.py +++ b/packages/reflex-base/src/reflex_base/utils/log.py @@ -41,6 +41,7 @@ if TYPE_CHECKING: from collections.abc import Hashable, Iterator + from typing import TextIO # Level between INFO and WARNING for user-facing success messages. SUCCESS = 25 @@ -311,11 +312,10 @@ def _log_file_path() -> Path: """ from reflex_base.environment import environment - if env_log_file := environment.REFLEX_LOG_FILE.get(): - return env_log_file - subseconds = int((time.time() % 1) * 1000) - timestamp = time.strftime("%Y-%m-%d_%H-%M-%S") + f"_{subseconds:03d}" - log_file = Reflex.DIR / "logs" / (timestamp + ".log") + if not (log_file := environment.REFLEX_LOG_FILE.get()): + subseconds = int((time.time() % 1) * 1000) + timestamp = time.strftime("%Y-%m-%d_%H-%M-%S") + f"_{subseconds:03d}" + log_file = Reflex.DIR / "logs" / (timestamp + ".log") log_file.parent.mkdir(parents=True, exist_ok=True) return log_file @@ -334,6 +334,18 @@ def _file_handler() -> logging.FileHandler: return handler +def log_file_stream() -> TextIO: + """Open (once) and return the stream of the full-logging file. + + The legacy ``console`` file writer renders through this same stream, so a + single file holds every record no matter which API produced it. + + Returns: + The writable stream of the full-logging file. + """ + return _file_handler().stream + + @once def _console_handler() -> RichConsoleHandler: """Create the rich console handler. @@ -407,7 +419,14 @@ def dedupe_once(key: Hashable) -> bool: return _dedupe_filter().register(key) -def emit_json_print(msg: str, *, dedupe: bool = False, stderr: bool = False): +def emit_json_print( + msg: str, + *, + level: str = "info", + dedupe: bool = False, + stderr: bool = False, + **fields, +): """Emit a plain console message as a JSON record. Used by ``console.print`` in JSON mode so the output stream stays @@ -416,18 +435,21 @@ def emit_json_print(msg: str, *, dedupe: bool = False, stderr: bool = False): Args: msg: The message. + level: The severity to report, matching the calling console helper. dedupe: If True, suppress repeats of the same message. stderr: Whether the message targets stderr. + fields: Extra fields to include in the record. """ if dedupe and not dedupe_once(("print", msg)): return _write_json( { "timestamp": datetime.datetime.now(tz=datetime.timezone.utc).isoformat(), - "level": "info", + "level": level, "logger": "reflex.console", "message": strip_markup(msg), "pid": os.getpid(), + **fields, }, stderr=stderr, ) @@ -469,10 +491,10 @@ def bootstrap(): for name in PACKAGE_LOGGER_NAMES: child = logging.getLogger(name) child.parent = _REFLEX_LOGGER - child.propagate = True - # Inherit the effective level from "reflex"; setLevel also clears the - # isEnabledFor caches, which reparenting alone does not. - child.setLevel(logging.NOTSET) + # Re-set the level a logger already has: that leaves an application's + # own configuration untouched while clearing the isEnabledFor caches, + # which reparenting alone does not do. + child.setLevel(child.level) if is_managed_mode(): configure() diff --git a/reflex/utils/exec.py b/reflex/utils/exec.py index 36cbbfe2767..8ad2fa5f631 100644 --- a/reflex/utils/exec.py +++ b/reflex/utils/exec.py @@ -814,7 +814,7 @@ def run_granian_backend_prod( def output_system_info(): """Show system information if the loglevel is in DEBUG.""" - if console._LOG_LEVEL > constants.LogLevel.DEBUG: + if not console.is_debug(): return from reflex.utils import js_runtimes diff --git a/reflex/utils/export.py b/reflex/utils/export.py index d45db0fdcdd..2c4493d2bc9 100644 --- a/reflex/utils/export.py +++ b/reflex/utils/export.py @@ -22,7 +22,7 @@ def export( api_url: str | None = None, deploy_url: str | None = None, env: constants.Env = constants.Env.PROD, - loglevel: constants.LogLevel = console._LOG_LEVEL, + loglevel: constants.LogLevel | None = None, backend_excluded_dirs: tuple[Path, ...] = (), prerender_routes: bool = True, ): @@ -37,7 +37,7 @@ def export( api_url: The API URL to use. Defaults to None. deploy_url: The deploy URL to use. Defaults to None. env: The environment to use. Defaults to constants.Env.PROD. - loglevel: The log level to use. Defaults to console._LOG_LEVEL. + loglevel: The log level to use. Defaults to the current log level. backend_excluded_dirs: A tuple of files or directories to exclude from the backend zip. Defaults to (). prerender_routes: Whether to prerender the routes. Defaults to True. """ diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index 947fd51bb70..daa15cda66e 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -310,6 +310,7 @@ def test_console_deprecate_preserves_rich_print_kwargs(monkeypatch): rich_print.assert_called_once_with( "[yellow]DeprecationWarning: OldFeature has been deprecated in version " "0.9.9. Use NewFeature. It will be completely removed in 1.0.[/yellow]", + level="warning", markup=False, ) @@ -332,6 +333,54 @@ def test_console_rule_json_mode(monkeypatch, capsys): assert out == "" +def test_console_json_mode_preserves_severity(monkeypatch, capsys): + """Legacy helpers keep their severity in the JSON stream.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + console.error("boom") + console.warn("careful") + console.success("done") + out, err = capsys.readouterr() + error_record = json.loads(err) + assert (error_record["level"], error_record["message"]) == ("error", "boom") + warning_record, success_record = (json.loads(line) for line in out.splitlines()) + assert (warning_record["level"], warning_record["message"]) == ( + "warning", + "Warning: careful", + ) + assert (success_record["level"], success_record["message"]) == ( + "success", + "Success: done", + ) + + +def test_console_log_json_mode(monkeypatch, capsys): + """console.log emits a JSON record instead of a timestamped rich line.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + console.log("compiling app") + out, _ = capsys.readouterr() + assert json.loads(out)["message"] == "compiling app" + + +def test_console_print_table_json_mode(monkeypatch, capsys): + """Tables stay in the machine-readable stream as structured rows.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + console.print_table([["app", "running"]], headers=["name", "status"]) + out, _ = capsys.readouterr() + assert json.loads(out)["table"] == { + "headers": ["name", "status"], + "rows": [["app", "running"]], + } + + +def test_poor_progress_json_mode(monkeypatch, capsys): + """The fallback progress bar does not write plain text in JSON mode.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + progress = console.PoorProgress() + progress.advance(progress.add_task("compile", total=2)) + out, _ = capsys.readouterr() + assert json.loads(out)["message"] == "Progress: 1/2" + + def _file_record(msg: str, *, rich: bool = False) -> logging.LogRecord: record = logging.LogRecord( name="reflex.test", @@ -363,6 +412,39 @@ def test_log_file_path_honors_env(monkeypatch, tmp_path): assert log._log_file_path() == log_file +def test_log_file_path_creates_parent_of_configured_path(monkeypatch, tmp_path): + """A configured path pointing into a new directory is made writable.""" + log_file = tmp_path / "nested" / "dir" / "my.log" + monkeypatch.setenv("REFLEX_LOG_FILE", str(log_file)) + assert log._log_file_path() == log_file + assert log_file.parent.is_dir() + + +def test_console_and_pipeline_share_one_log_file(monkeypatch, tmp_path): + """Legacy console file output lands in the pipeline's log file.""" + log_file = tmp_path / "full.log" + handler = logging.FileHandler(log_file, mode="w", encoding="utf-8") + monkeypatch.setattr(log, "_file_handler", lambda: handler) + # Bypass the ``once`` cache so the console reopens against this handler. + monkeypatch.setattr( + console, + "log_file_console", + console.log_file_console.__wrapped__, # pyright: ignore[reportFunctionMemberAccess] + ) + reflex_logger = logging.getLogger("reflex") + reflex_logger.addHandler(handler) + try: + console.print_to_log_file("from the legacy console") + logger.warning("from the logging pipeline") + handler.flush() + contents = log_file.read_text(encoding="utf-8") + finally: + reflex_logger.removeHandler(handler) + handler.close() + assert "from the legacy console" in contents + assert "from the logging pipeline" in contents + + def test_every_logging_package_root_is_registered(): """Workspace packages that log must appear in PACKAGE_LOGGER_NAMES. @@ -409,6 +491,17 @@ def test_bootstrap_parents_package_loggers_under_reflex(library_mode): assert parents[-1] is logging.getLogger() +def test_bootstrap_preserves_application_logger_config(library_mode): + """An app's own level on a package logger survives bootstrap.""" + package_logger = logging.getLogger(log.PACKAGE_LOGGER_NAMES[0]) + package_logger.setLevel(logging.CRITICAL) + try: + log.bootstrap() + assert package_logger.level == logging.CRITICAL + finally: + package_logger.setLevel(logging.NOTSET) + + def test_bootstrap_configures_when_managed(monkeypatch): """Workers inherit the CLI marker and attach sinks at import time.""" monkeypatch.setenv(log._MANAGED_ENV_VAR, "true") diff --git a/tests/units/utils/test_utils.py b/tests/units/utils/test_utils.py index 2d210d33d8c..ceb7cb3d86a 100644 --- a/tests/units/utils/test_utils.py +++ b/tests/units/utils/test_utils.py @@ -786,7 +786,7 @@ def test_output_system_info(mocker: MockerFixture): This test makes no assertions about the output, other than it executes without crashing. """ - mocker.patch("reflex_base.utils.console._LOG_LEVEL", constants.LogLevel.DEBUG) + mocker.patch("reflex_base.utils.log._log_level", constants.LogLevel.DEBUG) utils_exec.output_system_info() From d710729e539a4073b3894fe888b8baeda698c631 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 17 Aug 2026 22:30:30 +0000 Subject: [PATCH 04/11] chore(news): name the log pipeline fragments after the PR --- news/{+eng-10963-log-pipeline.feature.md => 6863.feature.md} | 0 .../news/{+eng-10963-log-pipeline.feature.md => 6863.feature.md} | 0 2 files changed, 0 insertions(+), 0 deletions(-) rename news/{+eng-10963-log-pipeline.feature.md => 6863.feature.md} (100%) rename packages/reflex-base/news/{+eng-10963-log-pipeline.feature.md => 6863.feature.md} (100%) diff --git a/news/+eng-10963-log-pipeline.feature.md b/news/6863.feature.md similarity index 100% rename from news/+eng-10963-log-pipeline.feature.md rename to news/6863.feature.md diff --git a/packages/reflex-base/news/+eng-10963-log-pipeline.feature.md b/packages/reflex-base/news/6863.feature.md similarity index 100% rename from packages/reflex-base/news/+eng-10963-log-pipeline.feature.md rename to packages/reflex-base/news/6863.feature.md From ba1cffe42c1dc22c19a1e4a432fc00e7e5624db2 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 17 Aug 2026 22:47:01 +0000 Subject: [PATCH 05/11] test(log): key the JSON console assertions by message --- tests/units/reflex_base/utils/test_log.py | 23 +++++++++++------------ 1 file changed, 11 insertions(+), 12 deletions(-) diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index daa15cda66e..e9888bd62f5 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -340,17 +340,15 @@ def test_console_json_mode_preserves_severity(monkeypatch, capsys): console.warn("careful") console.success("done") out, err = capsys.readouterr() - error_record = json.loads(err) - assert (error_record["level"], error_record["message"]) == ("error", "boom") - warning_record, success_record = (json.loads(line) for line in out.splitlines()) - assert (warning_record["level"], warning_record["message"]) == ( - "warning", - "Warning: careful", - ) - assert (success_record["level"], success_record["message"]) == ( - "success", - "Success: done", - ) + # Every line stays parseable; index by message so an unrelated record + # (a deprecation warning from the helper itself) cannot break this. + records = { + record["message"]: record + for record in map(json.loads, (out + err).splitlines()) + } + assert records["boom"]["level"] == "error" + assert records["Warning: careful"]["level"] == "warning" + assert records["Success: done"]["level"] == "success" def test_console_log_json_mode(monkeypatch, capsys): @@ -358,7 +356,8 @@ def test_console_log_json_mode(monkeypatch, capsys): monkeypatch.setenv("REFLEX_LOG_JSON", "true") console.log("compiling app") out, _ = capsys.readouterr() - assert json.loads(out)["message"] == "compiling app" + messages = [json.loads(line)["message"] for line in out.splitlines()] + assert "compiling app" in messages def test_console_print_table_json_mode(monkeypatch, capsys): From dfea7749b9ba939b877aa3f92d602b5113708161 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 17 Aug 2026 22:57:26 +0000 Subject: [PATCH 06/11] fix(log): keep canonical JSON fields authoritative in emit_json_print --- packages/reflex-base/src/reflex_base/utils/log.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/reflex-base/src/reflex_base/utils/log.py b/packages/reflex-base/src/reflex_base/utils/log.py index e4614ee9aba..85d81c5c7ad 100644 --- a/packages/reflex-base/src/reflex_base/utils/log.py +++ b/packages/reflex-base/src/reflex_base/utils/log.py @@ -444,12 +444,13 @@ def emit_json_print( return _write_json( { + # Extras first: the canonical fields below always win. + **fields, "timestamp": datetime.datetime.now(tz=datetime.timezone.utc).isoformat(), "level": level, "logger": "reflex.console", "message": strip_markup(msg), "pid": os.getpid(), - **fields, }, stderr=stderr, ) From 5a945120ff8da8c1221b9472356f2d67a7eb1413 Mon Sep 17 00:00:00 2001 From: Farhan Date: Tue, 18 Aug 2026 19:46:12 +0500 Subject: [PATCH 07/11] perf(log): self-bootstrap the pipeline to keep `import reflex` lazy MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Eagerly importing reflex_base.utils.log from reflex/__init__.py dragged in rich and 159 other modules, defeating the lazy_loader design (median import time 53.7ms vs 1.2ms, 46x). Reparenting is permanent, so bootstrap() now runs in log.py's own module body — console.py imports it at module scope, so the hierarchy is fixed the moment reflex does anything. Also: print tracebacks with soft_wrap so file paths survive narrow terminals, and point deprecation JSON records at the user call site instead of the framework frame. Adds a cold-import CodSpeed benchmark so the next eager import shows up as a regression. --- .../reflex-base/src/reflex_base/utils/log.py | 38 +++++++++---- pyi_hashes.json | 2 +- reflex/__init__.py | 12 ++--- tests/benchmarks/test_import.py | 27 ++++++++++ tests/units/reflex_base/utils/test_log.py | 53 +++++++++++++++++++ 5 files changed, 114 insertions(+), 18 deletions(-) create mode 100644 tests/benchmarks/test_import.py diff --git a/packages/reflex-base/src/reflex_base/utils/log.py b/packages/reflex-base/src/reflex_base/utils/log.py index 85d81c5c7ad..feb58758aa0 100644 --- a/packages/reflex-base/src/reflex_base/utils/log.py +++ b/packages/reflex-base/src/reflex_base/utils/log.py @@ -1,9 +1,11 @@ """Standard-library logging pipeline with rich rendering and JSON output. Reflex modules log through plain ``logging.getLogger(__name__)`` loggers. -At import time :func:`bootstrap` parents every workspace package logger -(``reflex_base``, ``reflex_cli``, ``reflex_components_*``) under the single -``reflex`` logger, so downstream code tunes all reflex logging in one place +When this module first loads (``reflex_base.utils.console`` imports it at +module scope, so that happens the moment reflex does anything) :func:`bootstrap` +parents every workspace package logger (``reflex_base``, ``reflex_cli``, +``reflex_components_*``) under the single ``reflex`` logger, so downstream +code tunes all reflex logging in one place (``logging.getLogger("reflex")``) or per package, with standard stdlib APIs. Handlers attach only in *managed* mode, i.e. when running under the reflex @@ -210,7 +212,13 @@ def emit(self, record: logging.LogRecord): ) if record.exc_info and record.exc_info[0] is not None: # Tracebacks may contain user data; never parse them as markup. - console.print(self.format_exception(record), style=style, markup=False) + # Never word-wrap them either: wrapping breaks file paths. + console.print( + self.format_exception(record), + style=style, + markup=False, + soft_wrap=True, + ) except Exception: self.handleError(record) @@ -265,7 +273,10 @@ def emit(self, record: logging.LogRecord): "level": logging.getLevelName(record.levelno).lower(), "logger": record.name, "message": message, - "location": f"{record.pathname}:{record.lineno}", + # Records may carry an explicit location (e.g. deprecations + # point at the user call site, not the framework frame). + "location": getattr(record, "location", None) + or f"{record.pathname}:{record.lineno}", "pid": record.process, } for field in self.extra_fields: @@ -482,9 +493,9 @@ def enable_managed_logging(): def bootstrap(): """Parent the package loggers under the top-level ``reflex`` logger. - Called at ``import reflex`` time, so it must stay import-light (no - :mod:`reflex_base.environment`). The manual parent assignment is permanent: - the logging manager only fixes up parents when it creates a logger, and + Runs at the bottom of this module, so importing the pipeline is enough to + fix up the hierarchy. The manual parent assignment is permanent: the + logging manager only fixes up parents when it creates a logger, and loggers created later under a package root chain to the existing root. In managed mode (marker inherited from the CLI) the sinks attach immediately so worker records render from the first line. @@ -717,6 +728,7 @@ def deprecate( del kwargs dedupe_key = feature_name loc = "" + user_location = None # See if we can find where the deprecation exists in "user code" origin_frame = _get_first_non_framework_frame() @@ -725,7 +737,8 @@ def deprecate( cwd = Path.cwd() if filename.is_relative_to(cwd): filename = filename.relative_to(cwd) - loc = f" ({filename}:{origin_frame.f_lineno})" + user_location = f"{filename}:{origin_frame.f_lineno}" + loc = f" ({user_location})" dedupe_key = f"{dedupe_key} {loc}" # Claim the key up front so repeat warnings skip formatting and emission @@ -744,5 +757,12 @@ def deprecate( "feature_name": feature_name, "deprecation_version": deprecation_version, "removal_version": removal_version, + # Machine consumers need the user call site, not this frame. + "location": user_location, }, ) + + +# Reparenting is permanent, so it happens the moment the pipeline loads — +# keeping ``import reflex`` itself free of this module (and rich). +bootstrap() diff --git a/pyi_hashes.json b/pyi_hashes.json index eb5902a8e82..fc6c747e540 100644 --- a/pyi_hashes.json +++ b/pyi_hashes.json @@ -118,7 +118,7 @@ "packages/reflex-components-recharts/src/reflex_components_recharts/polar.pyi": "99ebcfc07868061bdc3c2010d85a153f", "packages/reflex-components-recharts/src/reflex_components_recharts/recharts.pyi": "4f6c26f8c76543cc41e2b9dc400ece8a", "packages/reflex-components-sonner/src/reflex_components_sonner/toast.pyi": "f170ac685b6ba5892370166c80684db3", - "reflex/__init__.pyi": "61b2cc37c3d2473c99f3023c59627d51", + "reflex/__init__.pyi": "a3e1782fab4a9aed55f66cc98af8c217", "reflex/components/__init__.pyi": "9facd05a776d0641432696bbf8e34388", "reflex/experimental/memo.pyi": "bc8b48357bef580e70a5881b65d3d3f7" } diff --git a/reflex/__init__.py b/reflex/__init__.py index 66b77205ae2..b992aef360a 100644 --- a/reflex/__init__.py +++ b/reflex/__init__.py @@ -87,18 +87,14 @@ import sys from reflex_base.utils import lazy_loader -from reflex_base.utils import log as _log - -# Parent the workspace package loggers under the single "reflex" logger so -# all reflex logging is tunable in one place. Sinks attach only when the -# reflex CLI manages this process, keeping this import cheap and leaving -# library users' logging configuration untouched. -_log.bootstrap() -del _log if sys.version_info < (3, 11): import logging + # Loading the pipeline parents the package loggers and, under the CLI, + # attaches the sinks so this warning renders like every other record. + import reflex_base.utils.log + logging.getLogger(__name__).warning( "Reflex support for Python 3.10 is deprecated and will be removed in a future release. Please upgrade to Python 3.11 or higher for continued support." ) diff --git a/tests/benchmarks/test_import.py b/tests/benchmarks/test_import.py new file mode 100644 index 00000000000..5bd9e3f63a3 --- /dev/null +++ b/tests/benchmarks/test_import.py @@ -0,0 +1,27 @@ +import importlib +import sys + +from pytest_codspeed import BenchmarkFixture + + +def _wipe_reflex_modules(): + # Drop every reflex workspace module (and rich, which must stay lazy) so + # each round measures a cold `import reflex`. + for name in list(sys.modules): + top = name.partition(".")[0] + if top.startswith("reflex") or top == "rich": + del sys.modules[name] + + +def test_import_reflex(benchmark: BenchmarkFixture): + saved = sys.modules.copy() + try: + + def cold_import(): + _wipe_reflex_modules() + importlib.import_module("reflex") + + benchmark(cold_import) + finally: + sys.modules.clear() + sys.modules.update(saved) diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index e9888bd62f5..943ce4c9631 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -2,11 +2,15 @@ import json import logging +import subprocess +import sys +from pathlib import Path from unittest import mock import pytest from reflex_base.constants import LogLevel from reflex_base.utils import console, log +from rich.console import Console logger = logging.getLogger("reflex_base.tests.logs") @@ -516,3 +520,52 @@ def test_library_mode_records_propagate_to_root(library_mode, caplog): with caplog.at_level(logging.INFO, logger="reflex"): logger.info("through the root") assert "through the root" in caplog.text + + +def test_import_reflex_stays_light(): + """``import reflex`` must not drag in the log pipeline or rich. + + The pipeline self-bootstraps when its module first loads (which importing + ``reflex_base.utils.console`` guarantees), so the root package import can + stay lazy. + """ + script = ( + "import sys\n" + "import reflex\n" + "assert 'reflex_base.utils.log' not in sys.modules, 'log loaded eagerly'\n" + "assert 'rich' not in sys.modules, 'rich loaded eagerly'\n" + "import logging\n" + "import reflex_base.utils.console\n" + "assert logging.getLogger('reflex_base').parent is logging.getLogger('reflex')\n" + ) + subprocess.run([sys.executable, "-c", script], check=True) + + +def test_traceback_file_paths_are_not_wrapped(monkeypatch, capsys): + """Tracebacks print without word-wrapping so file paths survive intact.""" + monkeypatch.setattr( + log, "_console_stderr", Console(stderr=True, highlight=False, width=40) + ) + try: + _ = 1 / 0 + except ZeroDivisionError: + logger.exception("failed") + _, err = capsys.readouterr() + assert f'File "{__file__}"' in err + + +def test_deprecate_json_location_is_user_frame(monkeypatch, capsys): + """Deprecation JSON records locate the user call site, not the framework.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + log.deprecate( + feature_name="LocatedFeature", + reason="Use something else.", + deprecation_version="0.1.0", + removal_version="1.0", + ) + out, _ = capsys.readouterr() + location = json.loads(out)["location"] + path, _, lineno = location.rpartition(":") + assert Path(path).name == Path(__file__).name + assert lineno.isdigit() From 20a24275421ebec2896511941b3c71eaf8441287 Mon Sep 17 00:00:00 2001 From: Farhan Date: Tue, 18 Aug 2026 19:56:20 +0500 Subject: [PATCH 08/11] test(log): allow the eager pipeline import on py<3.11 in the lazy test reflex/__init__.py imports the pipeline on 3.10 on purpose, so the 3.10-deprecation warning renders through the sinks; the import-lightness assertions only apply on 3.11+. --- tests/units/reflex_base/utils/test_log.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index 943ce4c9631..bd6470c35ee 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -532,8 +532,10 @@ def test_import_reflex_stays_light(): script = ( "import sys\n" "import reflex\n" - "assert 'reflex_base.utils.log' not in sys.modules, 'log loaded eagerly'\n" - "assert 'rich' not in sys.modules, 'rich loaded eagerly'\n" + # On py<3.11 the 3.10-deprecation warning imports the pipeline itself. + "if sys.version_info >= (3, 11):\n" + " assert 'reflex_base.utils.log' not in sys.modules, 'log loaded eagerly'\n" + " assert 'rich' not in sys.modules, 'rich loaded eagerly'\n" "import logging\n" "import reflex_base.utils.console\n" "assert logging.getLogger('reflex_base').parent is logging.getLogger('reflex')\n" From 931a050afd1c625bcd2fcbd7b2fca3b59a282863 Mon Sep 17 00:00:00 2001 From: Farhan Date: Tue, 18 Aug 2026 20:09:04 +0500 Subject: [PATCH 09/11] fix(init): keep reflex_base out of the rx namespace on py3.10 The dotted side-effect import bound `reflex_base` in reflex/__init__.py globals on 3.10 only, so `rx.reflex_base` existed on that version alone. Import the pipeline through a private alias and delete it, as the block already does for logging. --- pyi_hashes.json | 2 +- reflex/__init__.py | 4 ++-- tests/units/reflex_base/utils/test_log.py | 2 ++ 3 files changed, 5 insertions(+), 3 deletions(-) diff --git a/pyi_hashes.json b/pyi_hashes.json index fc6c747e540..fe42ed503bf 100644 --- a/pyi_hashes.json +++ b/pyi_hashes.json @@ -118,7 +118,7 @@ "packages/reflex-components-recharts/src/reflex_components_recharts/polar.pyi": "99ebcfc07868061bdc3c2010d85a153f", "packages/reflex-components-recharts/src/reflex_components_recharts/recharts.pyi": "4f6c26f8c76543cc41e2b9dc400ece8a", "packages/reflex-components-sonner/src/reflex_components_sonner/toast.pyi": "f170ac685b6ba5892370166c80684db3", - "reflex/__init__.pyi": "a3e1782fab4a9aed55f66cc98af8c217", + "reflex/__init__.pyi": "26700d94e31c2683fb54f5a8ef9e2ca4", "reflex/components/__init__.pyi": "9facd05a776d0641432696bbf8e34388", "reflex/experimental/memo.pyi": "bc8b48357bef580e70a5881b65d3d3f7" } diff --git a/reflex/__init__.py b/reflex/__init__.py index b992aef360a..90b1c0572fc 100644 --- a/reflex/__init__.py +++ b/reflex/__init__.py @@ -93,12 +93,12 @@ # Loading the pipeline parents the package loggers and, under the CLI, # attaches the sinks so this warning renders like every other record. - import reflex_base.utils.log + from reflex_base.utils import log as _log logging.getLogger(__name__).warning( "Reflex support for Python 3.10 is deprecated and will be removed in a future release. Please upgrade to Python 3.11 or higher for continued support." ) - del logging + del logging, _log del sys from reflex_components_radix.mappings import RADIX_MAPPING # noqa: E402 diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index bd6470c35ee..d4d69c4fd12 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -532,6 +532,8 @@ def test_import_reflex_stays_light(): script = ( "import sys\n" "import reflex\n" + # The package namespace must look the same on every Python version. + "assert 'reflex_base' not in vars(reflex), 'reflex_base leaked into rx'\n" # On py<3.11 the 3.10-deprecation warning imports the pipeline itself. "if sys.version_info >= (3, 11):\n" " assert 'reflex_base.utils.log' not in sys.modules, 'log loaded eagerly'\n" From da107930dcb0299c16daaedc59d389a46ade59d8 Mon Sep 17 00:00:00 2001 From: Farhan Date: Tue, 18 Aug 2026 20:17:07 +0500 Subject: [PATCH 10/11] refactor(init): drop the log pipeline import from the py3.10 warning branch The import only bought a "Warning:" prefix for worker subprocesses on a deprecated Python; the CLI parent has not enabled managed mode at import time anyway, so the warning goes through logging.lastResort regardless. reflex/__init__.py now has no knowledge of the pipeline on any version, and the lazy-import test needs no version branch. --- pyi_hashes.json | 2 +- reflex/__init__.py | 6 +----- tests/units/reflex_base/utils/test_log.py | 8 ++------ 3 files changed, 4 insertions(+), 12 deletions(-) diff --git a/pyi_hashes.json b/pyi_hashes.json index fe42ed503bf..fc6c747e540 100644 --- a/pyi_hashes.json +++ b/pyi_hashes.json @@ -118,7 +118,7 @@ "packages/reflex-components-recharts/src/reflex_components_recharts/polar.pyi": "99ebcfc07868061bdc3c2010d85a153f", "packages/reflex-components-recharts/src/reflex_components_recharts/recharts.pyi": "4f6c26f8c76543cc41e2b9dc400ece8a", "packages/reflex-components-sonner/src/reflex_components_sonner/toast.pyi": "f170ac685b6ba5892370166c80684db3", - "reflex/__init__.pyi": "26700d94e31c2683fb54f5a8ef9e2ca4", + "reflex/__init__.pyi": "a3e1782fab4a9aed55f66cc98af8c217", "reflex/components/__init__.pyi": "9facd05a776d0641432696bbf8e34388", "reflex/experimental/memo.pyi": "bc8b48357bef580e70a5881b65d3d3f7" } diff --git a/reflex/__init__.py b/reflex/__init__.py index 90b1c0572fc..8aa2bfc2880 100644 --- a/reflex/__init__.py +++ b/reflex/__init__.py @@ -91,14 +91,10 @@ if sys.version_info < (3, 11): import logging - # Loading the pipeline parents the package loggers and, under the CLI, - # attaches the sinks so this warning renders like every other record. - from reflex_base.utils import log as _log - logging.getLogger(__name__).warning( "Reflex support for Python 3.10 is deprecated and will be removed in a future release. Please upgrade to Python 3.11 or higher for continued support." ) - del logging, _log + del logging del sys from reflex_components_radix.mappings import RADIX_MAPPING # noqa: E402 diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index d4d69c4fd12..943ce4c9631 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -532,12 +532,8 @@ def test_import_reflex_stays_light(): script = ( "import sys\n" "import reflex\n" - # The package namespace must look the same on every Python version. - "assert 'reflex_base' not in vars(reflex), 'reflex_base leaked into rx'\n" - # On py<3.11 the 3.10-deprecation warning imports the pipeline itself. - "if sys.version_info >= (3, 11):\n" - " assert 'reflex_base.utils.log' not in sys.modules, 'log loaded eagerly'\n" - " assert 'rich' not in sys.modules, 'rich loaded eagerly'\n" + "assert 'reflex_base.utils.log' not in sys.modules, 'log loaded eagerly'\n" + "assert 'rich' not in sys.modules, 'rich loaded eagerly'\n" "import logging\n" "import reflex_base.utils.console\n" "assert logging.getLogger('reflex_base').parent is logging.getLogger('reflex')\n" From c8998f0a4764558f9a1dbcd2720b680a1301981d Mon Sep 17 00:00:00 2001 From: Farhan Date: Tue, 18 Aug 2026 22:28:16 +0500 Subject: [PATCH 11/11] fix(log): never attach sinks from the import-time bootstrap bootstrap() ran configure() in managed mode, and configure() imports reflex_base.environment, which pulls in the component tree. Since the pipeline now bootstraps when log.py is first imported, a managed worker that touched reflex_base.vars before anything else closed a circular import (vars -> console -> log -> environment -> plugins -> components -> vars) and died with a partially initialized module. Import-time bootstrap now only reparents the package loggers, which is all it ever needed to do at import. Managed processes attach sinks via enable_managed_logging() (CLI) or ensure_configured() (workers, from get_config()), both of which run after imports have settled. --- .../reflex-base/src/reflex_base/utils/log.py | 12 ++++++---- tests/units/reflex_base/utils/test_log.py | 23 ++++++++++++++++--- 2 files changed, 27 insertions(+), 8 deletions(-) diff --git a/packages/reflex-base/src/reflex_base/utils/log.py b/packages/reflex-base/src/reflex_base/utils/log.py index feb58758aa0..c7c17e10bf7 100644 --- a/packages/reflex-base/src/reflex_base/utils/log.py +++ b/packages/reflex-base/src/reflex_base/utils/log.py @@ -484,7 +484,8 @@ def enable_managed_logging(): """Mark this process (and its subprocesses) as CLI-managed and attach sinks. Called from the reflex CLI entry point. Worker subprocesses inherit the - marker through the environment and configure themselves in bootstrap(). + marker through the environment and attach their sinks through + ensure_configured() once configuration is loaded. """ os.environ[_MANAGED_ENV_VAR] = "true" configure() @@ -497,8 +498,11 @@ def bootstrap(): fix up the hierarchy. The manual parent assignment is permanent: the logging manager only fixes up parents when it creates a logger, and loggers created later under a package root chain to the existing root. - In managed mode (marker inherited from the CLI) the sinks attach - immediately so worker records render from the first line. + Sinks are never attached here: that needs :mod:`reflex_base.environment` + (and with it the component tree), which is not safe to import from + within this module's own import. Managed processes attach them through + :func:`enable_managed_logging` (the CLI) or :func:`ensure_configured` + (workers, from ``get_config``). """ for name in PACKAGE_LOGGER_NAMES: child = logging.getLogger(name) @@ -507,8 +511,6 @@ def bootstrap(): # own configuration untouched while clearing the isEnabledFor caches, # which reparenting alone does not do. child.setLevel(child.level) - if is_managed_mode(): - configure() def configure(): diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index 943ce4c9631..cbb99c44f69 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -2,6 +2,7 @@ import json import logging +import os import subprocess import sys from pathlib import Path @@ -505,15 +506,31 @@ def test_bootstrap_preserves_application_logger_config(library_mode): package_logger.setLevel(logging.NOTSET) -def test_bootstrap_configures_when_managed(monkeypatch): - """Workers inherit the CLI marker and attach sinks at import time.""" +def test_bootstrap_never_attaches_sinks(monkeypatch): + """Import-time bootstrap only reparents; sinks wait for ensure_configured. + + Attaching sinks needs ``reflex_base.environment``, which imports the + component tree, so doing it at import time can close a circular import + (``vars`` -> ``console`` -> ``log`` -> ``environment`` -> ``vars``). + """ monkeypatch.setenv(log._MANAGED_ENV_VAR, "true") log._reset() log.bootstrap() - assert log._configured + assert not log._configured + assert log._console_handler() not in logging.getLogger("reflex").handlers + log.ensure_configured() assert log._console_handler() in logging.getLogger("reflex").handlers +def test_managed_worker_can_import_vars_first(): + """A managed worker importing ``reflex_base.vars`` before anything else works.""" + subprocess.run( + [sys.executable, "-c", "import reflex_base.vars"], + check=True, + env={**os.environ, log._MANAGED_ENV_VAR: "true"}, + ) + + def test_library_mode_records_propagate_to_root(library_mode, caplog): """Without the CLI, records reach root for the app (and pytest) to capture.""" log.bootstrap()