From f9584bd60091e3d54fcdd0f0150be0dee03f5c9e Mon Sep 17 00:00:00 2001 From: hippi345 <13539685+hippi345@users.noreply.github.com> Date: Tue, 27 Oct 2026 20:37:26 +0000 Subject: [PATCH 1/5] fix(log): show warnings when logging is not configured get_logger attached a NullHandler, which counts as a handler and stops Python from sending WARNING and above to logging.lastResort. Drop it so an application that has not configured logging still sees RedisVL warnings on stderr. Fixes #786 --- redisvl/utils/log.py | 14 +++---- tests/unit/test_log.py | 86 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 93 insertions(+), 7 deletions(-) create mode 100644 tests/unit/test_log.py diff --git a/redisvl/utils/log.py b/redisvl/utils/log.py index b78c20949..3808c7c53 100644 --- a/redisvl/utils/log.py +++ b/redisvl/utils/log.py @@ -2,14 +2,14 @@ def get_logger(name, log_level="info", fmt=None): - """Return a logger instance.""" + """Return a logger instance. + + No handler is attached. A ``NullHandler`` counts as a handler and stops + Python from sending WARNING and above to ``logging.lastResort`` (stderr) + when the application has not configured logging. + """ # Use file name if logger is in debug mode name = "RedisVL" if log_level == "debug" else name - logger = logging.getLogger(name) - - # Add a NullHandler to loggers to avoid "no handler found" warnings - if not logger.handlers: - logger.addHandler(logging.NullHandler()) - return logger + return logging.getLogger(name) diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py new file mode 100644 index 000000000..da8bac7ab --- /dev/null +++ b/tests/unit/test_log.py @@ -0,0 +1,86 @@ +"""Logging reaches stderr when the application has not configured logging. + +pytest's ``caplog`` fixture installs its own handler, so a test that uses it +passes even when ``get_logger`` swallows the record. These tests run in a +fresh interpreter and read stderr instead. +""" + +import subprocess +import sys +import textwrap + +from redisvl.utils.log import get_logger + + +def _run(script: str) -> subprocess.CompletedProcess[str]: + return subprocess.run( + [sys.executable, "-c", textwrap.dedent(script)], + capture_output=True, + text=True, + check=False, + ) + + +def _line_with(lines: list[str], message: str) -> str: + matched = [line for line in lines if message in line] + assert len(matched) == 1, lines + return matched[0] + + +def _same_handler_format(left: str, right: str) -> None: + """Both lines come from the same handler when only name and message differ.""" + + def normalize(line: str, name: str, message: str) -> str: + return line.replace(name, "NAME", 1).replace(message, "MSG", 1) + + assert normalize(left, "redisvl.demo", "from redisvl logger") == normalize( + right, "plain.demo", "from plain logger" + ) + + +def test_get_logger_does_not_attach_a_handler(): + name = "redisvl.test.nohandler" + logger = get_logger(name) + assert logger.handlers == [] + assert logger.propagate is True + + +def test_warning_reaches_stderr_without_logging_configuration(): + result = _run(""" + import logging + from redisvl.utils.log import get_logger + + logger = get_logger("redisvl.demo") + logger.info("redisvl info hidden") + logger.warning("from redisvl logger") + logger.error("from redisvl error") + logging.getLogger("plain.demo").warning("from plain logger") + """) + assert result.returncode == 0, result.stderr + assert "redisvl info hidden" not in result.stderr + stderr_lines = result.stderr.splitlines() + redis_line = _line_with(stderr_lines, "from redisvl logger") + _line_with(stderr_lines, "from redisvl error") + plain_line = _line_with(stderr_lines, "from plain logger") + _same_handler_format(redis_line, plain_line) + + +def test_configured_logging_still_receives_redisvl_warnings(): + result = _run(""" + import logging + import sys + + logging.basicConfig( + stream=sys.stdout, + format="APP %(levelname)s %(name)s %(message)s", + level=logging.WARNING, + ) + from redisvl.utils.log import get_logger + + get_logger("redisvl.demo").warning("configured redisvl warning") + """) + assert result.returncode == 0, result.stderr + assert result.stdout.splitlines() == [ + "APP WARNING redisvl.demo configured redisvl warning" + ] + assert "configured redisvl warning" not in result.stderr From 6a55dc73be28c36890bc81f4d18f79868f515724 Mon Sep 17 00:00:00 2001 From: hippi345 <13539685+hippi345@users.noreply.github.com> Date: Fri, 30 Oct 2026 18:45:53 +0000 Subject: [PATCH 2/5] fix(log,cli): keep stderr clean on CLI failures without hiding warnings Attach a default stderr handler on get_logger loggers so unconfigured apps still see WARNING+ on stderr (#786) while exc_info does not dump tracebacks there. CLI exception handlers only log when the host app configured logging. --- redisvl/cli/index.py | 6 ++---- redisvl/cli/migrate.py | 4 ++-- redisvl/cli/stats.py | 6 ++---- redisvl/cli/utils.py | 7 ++++++ redisvl/utils/log.py | 41 ++++++++++++++++++++++++++++++------ tests/unit/test_cli_index.py | 1 + tests/unit/test_log.py | 26 ++++++++++++++++++----- 7 files changed, 70 insertions(+), 21 deletions(-) diff --git a/redisvl/cli/index.py b/redisvl/cli/index.py index f4ce89710..6d0e117c5 100644 --- a/redisvl/cli/index.py +++ b/redisvl/cli/index.py @@ -10,6 +10,7 @@ add_json_output_flag, cli_print_json, create_redis_url, + log_cli_exception, ) from redisvl.exceptions import RedisSearchError from redisvl.index import SearchIndex @@ -20,9 +21,6 @@ ) from redisvl.redis.utils import convert_bytes from redisvl.schema.schema import IndexSchema -from redisvl.utils.log import get_logger - -logger = get_logger("[RedisVL]") # Exceptions commonly raised when loading or validating a schema path (-s). SCHEMA_INPUT_ERRORS = ( @@ -83,7 +81,7 @@ def __init__(self): try: args.handler(args) except Exception as e: - logger.error(e, exc_info=True) + log_cli_exception(e) print(str(e), file=sys.stderr) sys.exit(1) diff --git a/redisvl/cli/migrate.py b/redisvl/cli/migrate.py index 2e92c78dd..4b96fbba6 100644 --- a/redisvl/cli/migrate.py +++ b/redisvl/cli/migrate.py @@ -5,7 +5,7 @@ from pathlib import Path from typing import Optional -from redisvl.cli.utils import add_redis_connection_options, create_redis_url +from redisvl.cli.utils import add_redis_connection_options, create_redis_url, log_cli_exception from redisvl.migration import ( AsyncMigrationExecutor, BatchMigrationExecutor, @@ -74,7 +74,7 @@ def __init__(self): getattr(self, command)() except Exception as e: print(f"Error: {e}", file=sys.stderr) - logger.error(e) + log_cli_exception(e) sys.exit(1) def helper(self): diff --git a/redisvl/cli/stats.py b/redisvl/cli/stats.py index 2614bfae1..d9a8fdbe4 100644 --- a/redisvl/cli/stats.py +++ b/redisvl/cli/stats.py @@ -10,13 +10,11 @@ add_json_output_flag, cli_print_json, create_redis_url, + log_cli_exception, ) from redisvl.exceptions import RedisSearchError from redisvl.index import SearchIndex from redisvl.schema.schema import IndexSchema -from redisvl.utils.log import get_logger - -logger = get_logger("[RedisVL]") # Exceptions commonly raised when loading or validating a schema path (-s). SCHEMA_INPUT_ERRORS = ( @@ -113,7 +111,7 @@ def __init__(self): try: self.stats(args) except Exception as e: - logger.error(e, exc_info=True) + log_cli_exception(e) print(str(e), file=sys.stderr) sys.exit(1) diff --git a/redisvl/cli/utils.py b/redisvl/cli/utils.py index b82f3c1f4..4f210a23d 100644 --- a/redisvl/cli/utils.py +++ b/redisvl/cli/utils.py @@ -1,4 +1,5 @@ import json +import logging import os from argparse import ArgumentParser, Namespace, _ArgumentGroup from typing import Any, Mapping, Union @@ -12,6 +13,12 @@ DEFAULT_REDIS_PORT = 6379 +def log_cli_exception(exc: BaseException) -> None: + """Record a CLI failure when the host application configured logging.""" + if logging.getLogger().handlers: + logger.error(exc, exc_info=True) + + def _has_explicit_connection_options(args: Namespace) -> bool: return any( ( diff --git a/redisvl/utils/log.py b/redisvl/utils/log.py index 3808c7c53..82e45b40d 100644 --- a/redisvl/utils/log.py +++ b/redisvl/utils/log.py @@ -1,15 +1,44 @@ import logging -def get_logger(name, log_level="info", fmt=None): - """Return a logger instance. +class _DefaultStderrHandler(logging.Handler): + """Emit WARNING+ when the application has not configured logging. - No handler is attached. A ``NullHandler`` counts as a handler and stops - Python from sending WARNING and above to ``logging.lastResort`` (stderr) - when the application has not configured logging. + ``NullHandler`` counts as a handler and prevents ``logging.lastResort`` + from running, which hid RedisVL warnings before #786. This handler forwards + WARNING and above to stderr (via ``lastResort``) when the root logger has + no handlers, and forwards to the root logger once logging is configured. + Exception tracebacks are not written here so CLI code can log with + ``exc_info`` for configured apps without duplicating tracebacks on stderr. """ + def __init__(self) -> None: + super().__init__(level=logging.WARNING) + + def emit(self, record: logging.LogRecord) -> None: + root = logging.getLogger() + if root.handlers: + root.handle(record) + return + clean = logging.makeLogRecord( + { + **record.__dict__, + "exc_info": None, + "exc_text": None, + "stack_info": None, + } + ) + logging.lastResort.handle(clean) + + +def get_logger(name, log_level="info", fmt=None): + """Return a logger instance.""" + # Use file name if logger is in debug mode name = "RedisVL" if log_level == "debug" else name - return logging.getLogger(name) + logger = logging.getLogger(name) + if not any(isinstance(h, _DefaultStderrHandler) for h in logger.handlers): + logger.addHandler(_DefaultStderrHandler()) + logger.propagate = False + return logger diff --git a/tests/unit/test_cli_index.py b/tests/unit/test_cli_index.py index 5833bd7ad..1522426e5 100644 --- a/tests/unit/test_cli_index.py +++ b/tests/unit/test_cli_index.py @@ -459,3 +459,4 @@ def test_index_runtime_errors( assert exc_info.value.code == 1 assert captured.out == "" assert captured.err != "" + assert "Traceback" not in captured.err diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index da8bac7ab..5adb70088 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -9,7 +9,7 @@ import sys import textwrap -from redisvl.utils.log import get_logger +from redisvl.utils.log import _DefaultStderrHandler, get_logger def _run(script: str) -> subprocess.CompletedProcess[str]: @@ -38,11 +38,12 @@ def normalize(line: str, name: str, message: str) -> str: ) -def test_get_logger_does_not_attach_a_handler(): - name = "redisvl.test.nohandler" +def test_get_logger_attaches_default_stderr_handler(): + name = "redisvl.test.stderr_handler" logger = get_logger(name) - assert logger.handlers == [] - assert logger.propagate is True + assert len(logger.handlers) == 1 + assert isinstance(logger.handlers[0], _DefaultStderrHandler) + assert logger.propagate is False def test_warning_reaches_stderr_without_logging_configuration(): @@ -65,6 +66,21 @@ def test_warning_reaches_stderr_without_logging_configuration(): _same_handler_format(redis_line, plain_line) +def test_error_with_exc_info_does_not_write_traceback_to_stderr(): + result = _run(""" + from redisvl.utils.log import get_logger + + logger = get_logger("redisvl.cli.test") + try: + raise RuntimeError("cli failure") + except RuntimeError as exc: + logger.error(exc, exc_info=True) + """) + assert result.returncode == 0, result.stderr + assert "cli failure" in result.stderr + assert "Traceback" not in result.stderr + + def test_configured_logging_still_receives_redisvl_warnings(): result = _run(""" import logging From da3b4c14c21184adeff101eef022e33259087c58 Mon Sep 17 00:00:00 2001 From: hippi345 <13539685+hippi345@users.noreply.github.com> Date: Sat, 31 Oct 2026 00:33:57 +0000 Subject: [PATCH 3/5] fix(log): propagate to configured loggers without duplicate stderr Stop forcing propagate=False on RedisVL loggers. The default stderr handler now no-ops when the application attached handlers on the root or a parent logger, so INFO/DEBUG and ancestor handlers work again while unconfigured WARNING+ output still reaches stderr without exc tracebacks. --- redisvl/cli/migrate.py | 6 +++++- redisvl/cli/utils.py | 5 ++--- redisvl/utils/log.py | 18 ++++++++++++---- tests/unit/test_log.py | 47 +++++++++++++++++++++++++++++++++++++++++- 4 files changed, 67 insertions(+), 9 deletions(-) diff --git a/redisvl/cli/migrate.py b/redisvl/cli/migrate.py index 4b96fbba6..881a0a0d9 100644 --- a/redisvl/cli/migrate.py +++ b/redisvl/cli/migrate.py @@ -5,7 +5,11 @@ from pathlib import Path from typing import Optional -from redisvl.cli.utils import add_redis_connection_options, create_redis_url, log_cli_exception +from redisvl.cli.utils import ( + add_redis_connection_options, + create_redis_url, + log_cli_exception, +) from redisvl.migration import ( AsyncMigrationExecutor, BatchMigrationExecutor, diff --git a/redisvl/cli/utils.py b/redisvl/cli/utils.py index 4f210a23d..cac7a66fc 100644 --- a/redisvl/cli/utils.py +++ b/redisvl/cli/utils.py @@ -1,12 +1,11 @@ import json -import logging import os from argparse import ArgumentParser, Namespace, _ArgumentGroup from typing import Any, Mapping, Union from urllib.parse import quote, urlparse, urlunparse from redisvl.redis.constants import REDIS_URL_ENV_VAR -from redisvl.utils.log import get_logger +from redisvl.utils.log import _has_application_handlers, get_logger logger = get_logger("[RedisVL]") DEFAULT_REDIS_HOST = "localhost" @@ -15,7 +14,7 @@ def log_cli_exception(exc: BaseException) -> None: """Record a CLI failure when the host application configured logging.""" - if logging.getLogger().handlers: + if _has_application_handlers(logger.name): logger.error(exc, exc_info=True) diff --git a/redisvl/utils/log.py b/redisvl/utils/log.py index 82e45b40d..092532f13 100644 --- a/redisvl/utils/log.py +++ b/redisvl/utils/log.py @@ -16,9 +16,7 @@ def __init__(self) -> None: super().__init__(level=logging.WARNING) def emit(self, record: logging.LogRecord) -> None: - root = logging.getLogger() - if root.handlers: - root.handle(record) + if _has_application_handlers(record.name): return clean = logging.makeLogRecord( { @@ -31,6 +29,19 @@ def emit(self, record: logging.LogRecord) -> None: logging.lastResort.handle(clean) +def _has_application_handlers(logger_name: str) -> bool: + """True when the host app attached handlers outside RedisVL's default.""" + root = logging.getLogger() + if root.handlers: + return True + parts = logger_name.split(".") + for i in range(len(parts), 0, -1): + for handler in logging.getLogger(".".join(parts[:i])).handlers: + if not isinstance(handler, _DefaultStderrHandler): + return True + return False + + def get_logger(name, log_level="info", fmt=None): """Return a logger instance.""" @@ -40,5 +51,4 @@ def get_logger(name, log_level="info", fmt=None): logger = logging.getLogger(name) if not any(isinstance(h, _DefaultStderrHandler) for h in logger.handlers): logger.addHandler(_DefaultStderrHandler()) - logger.propagate = False return logger diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index 5adb70088..9640888f8 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -43,7 +43,7 @@ def test_get_logger_attaches_default_stderr_handler(): logger = get_logger(name) assert len(logger.handlers) == 1 assert isinstance(logger.handlers[0], _DefaultStderrHandler) - assert logger.propagate is False + assert logger.propagate is True def test_warning_reaches_stderr_without_logging_configuration(): @@ -81,6 +81,51 @@ def test_error_with_exc_info_does_not_write_traceback_to_stderr(): assert "Traceback" not in result.stderr +def test_info_propagates_when_root_logging_is_configured_for_debug(): + result = _run(""" + import logging + import sys + + logging.basicConfig( + stream=sys.stdout, + format="APP %(levelname)s %(name)s %(message)s", + level=logging.DEBUG, + ) + from redisvl.utils.log import get_logger + + get_logger("redisvl.demo").info("configured redisvl info") + """) + assert result.returncode == 0, result.stderr + assert result.stdout.splitlines() == [ + "APP INFO redisvl.demo configured redisvl info" + ] + assert "configured redisvl info" not in result.stderr + + +def test_parent_logger_handlers_receive_redisvl_records(): + result = _run(""" + import logging + import sys + + parent = logging.getLogger("redisvl") + parent.setLevel(logging.INFO) + parent.addHandler( + logging.StreamHandler(sys.stdout) + ) + parent.handlers[0].setFormatter( + logging.Formatter("PARENT %(levelname)s %(name)s %(message)s") + ) + from redisvl.utils.log import get_logger + + get_logger("redisvl.demo").info("parent handler info") + """) + assert result.returncode == 0, result.stderr + assert result.stdout.splitlines() == [ + "PARENT INFO redisvl.demo parent handler info" + ] + assert "parent handler info" not in result.stderr + + def test_configured_logging_still_receives_redisvl_warnings(): result = _run(""" import logging From ba9f127e85e3d536024d2087af38be77a2633b74 Mon Sep 17 00:00:00 2001 From: hippi345 <13539685+hippi345@users.noreply.github.com> Date: Sat, 31 Oct 2026 03:11:57 +0000 Subject: [PATCH 4/5] fix(log): guard lastResort and dedupe hierarchical stderr handlers Only the innermost _DefaultStderrHandler for a record emits to lastResort so parent/child get_logger calls do not duplicate warnings. Skip emit when logging.lastResort is None per stdlib semantics. --- redisvl/utils/log.py | 23 ++++++++++++++++++++--- tests/unit/test_log.py | 24 ++++++++++++++++++++++++ 2 files changed, 44 insertions(+), 3 deletions(-) diff --git a/redisvl/utils/log.py b/redisvl/utils/log.py index 092532f13..24c3605ae 100644 --- a/redisvl/utils/log.py +++ b/redisvl/utils/log.py @@ -12,12 +12,15 @@ class _DefaultStderrHandler(logging.Handler): ``exc_info`` for configured apps without duplicating tracebacks on stderr. """ - def __init__(self) -> None: + def __init__(self, logger_name: str) -> None: super().__init__(level=logging.WARNING) + self._logger_name = logger_name def emit(self, record: logging.LogRecord) -> None: if _has_application_handlers(record.name): return + if _default_stderr_owner(record.name) != self._logger_name: + return clean = logging.makeLogRecord( { **record.__dict__, @@ -26,7 +29,21 @@ def emit(self, record: logging.LogRecord) -> None: "stack_info": None, } ) - logging.lastResort.handle(clean) + last_resort = logging.lastResort + if last_resort is not None: + last_resort.handle(clean) + + +def _default_stderr_owner(record_name: str) -> str | None: + """Logger name whose ``_DefaultStderrHandler`` should emit for ``record_name``.""" + parts = record_name.split(".") + owner: str | None = None + for i in range(1, len(parts) + 1): + candidate = ".".join(parts[:i]) + logger = logging.getLogger(candidate) + if any(isinstance(h, _DefaultStderrHandler) for h in logger.handlers): + owner = candidate + return owner def _has_application_handlers(logger_name: str) -> bool: @@ -50,5 +67,5 @@ def get_logger(name, log_level="info", fmt=None): logger = logging.getLogger(name) if not any(isinstance(h, _DefaultStderrHandler) for h in logger.handlers): - logger.addHandler(_DefaultStderrHandler()) + logger.addHandler(_DefaultStderrHandler(name)) return logger diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index 9640888f8..124be544a 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -145,3 +145,27 @@ def test_configured_logging_still_receives_redisvl_warnings(): "APP WARNING redisvl.demo configured redisvl warning" ] assert "configured redisvl warning" not in result.stderr + + +def test_parent_and_child_default_handlers_do_not_duplicate_stderr(): + result = _run(""" + from redisvl.utils.log import get_logger + + get_logger("redisvl") + get_logger("redisvl.demo").warning("single parent child warning") + """) + assert result.returncode == 0, result.stderr + _line_with(result.stderr.splitlines(), "single parent child warning") + + +def test_warning_emit_succeeds_when_last_resort_is_none(): + result = _run(""" + import logging + from redisvl.utils.log import get_logger + + logging.lastResort = None + get_logger("redisvl.demo").warning("suppressed by none last resort") + """) + assert result.returncode == 0, result.stderr + assert "suppressed by none last resort" not in result.stderr + assert "Traceback" not in result.stderr From 4264785c0c21dbefadc74fef3c8503b6ed74f3a4 Mon Sep 17 00:00:00 2001 From: hippi345 <13539685+hippi345@users.noreply.github.com> Date: Sat, 14 Nov 2026 18:45:04 +0000 Subject: [PATCH 5/5] fix(log): drop NullHandler and use stdlib lastResort (#786) Remove the custom _DefaultStderrHandler stack and return bare loggers from get_logger so WARNING+ reaches lastResort when the app has not configured logging. Stop duplicating CLI failures by removing logger calls where stderr already prints the error; add subprocess tests for #786 and for rvl index stderr shape. --- docs/concepts/queries.md | 2 +- redisvl/cli/index.py | 2 - redisvl/cli/migrate.py | 7 +- redisvl/cli/stats.py | 2 - redisvl/cli/utils.py | 8 +-- redisvl/utils/log.py | 63 +---------------- tests/unit/test_cli_index.py | 32 ++++++++- tests/unit/test_log.py | 128 ++--------------------------------- 8 files changed, 41 insertions(+), 203 deletions(-) diff --git a/docs/concepts/queries.md b/docs/concepts/queries.md index 9f6354241..3034b5a90 100644 --- a/docs/concepts/queries.md +++ b/docs/concepts/queries.md @@ -354,7 +354,7 @@ query = HybridQuery( RedisVL returns query results as a list of dictionaries, one per matched document. On Redis 8.8+ a document can occasionally come back with its field payload missing: the RediSearch worker pool now defaults to a nonzero number of background worker threads, and if a document — or one of its indexed fields — expires (via TTL or `HPEXPIRE`) at the exact moment a background search is reading it, the server returns the matched id with an empty field payload instead of dropping it from the result set. This is most likely in workloads that combine search with short TTLs, such as a semantic cache or chat history. -RedisVL detects and **silently skips** such a document (logging at `WARNING` level) whenever the query type guarantees a field would be present on a healthy match: +RedisVL detects and **skips** such a document (logging at `WARNING` level) whenever the query type guarantees a field would be present on a healthy match: - **`VectorQuery` / `VectorRangeQuery`** with `return_score=True` (the default) — a healthy match always carries a `vector_distance`. - **`FilterQuery` on JSON storage** that returns the whole object — a healthy match always carries its JSON payload. diff --git a/redisvl/cli/index.py b/redisvl/cli/index.py index 6d0e117c5..888b35aa3 100644 --- a/redisvl/cli/index.py +++ b/redisvl/cli/index.py @@ -10,7 +10,6 @@ add_json_output_flag, cli_print_json, create_redis_url, - log_cli_exception, ) from redisvl.exceptions import RedisSearchError from redisvl.index import SearchIndex @@ -81,7 +80,6 @@ def __init__(self): try: args.handler(args) except Exception as e: - log_cli_exception(e) print(str(e), file=sys.stderr) sys.exit(1) diff --git a/redisvl/cli/migrate.py b/redisvl/cli/migrate.py index 881a0a0d9..3906531ae 100644 --- a/redisvl/cli/migrate.py +++ b/redisvl/cli/migrate.py @@ -5,11 +5,7 @@ from pathlib import Path from typing import Optional -from redisvl.cli.utils import ( - add_redis_connection_options, - create_redis_url, - log_cli_exception, -) +from redisvl.cli.utils import add_redis_connection_options, create_redis_url from redisvl.migration import ( AsyncMigrationExecutor, BatchMigrationExecutor, @@ -78,7 +74,6 @@ def __init__(self): getattr(self, command)() except Exception as e: print(f"Error: {e}", file=sys.stderr) - log_cli_exception(e) sys.exit(1) def helper(self): diff --git a/redisvl/cli/stats.py b/redisvl/cli/stats.py index d9a8fdbe4..aa27b85e1 100644 --- a/redisvl/cli/stats.py +++ b/redisvl/cli/stats.py @@ -10,7 +10,6 @@ add_json_output_flag, cli_print_json, create_redis_url, - log_cli_exception, ) from redisvl.exceptions import RedisSearchError from redisvl.index import SearchIndex @@ -111,7 +110,6 @@ def __init__(self): try: self.stats(args) except Exception as e: - log_cli_exception(e) print(str(e), file=sys.stderr) sys.exit(1) diff --git a/redisvl/cli/utils.py b/redisvl/cli/utils.py index cac7a66fc..b82f3c1f4 100644 --- a/redisvl/cli/utils.py +++ b/redisvl/cli/utils.py @@ -5,19 +5,13 @@ from urllib.parse import quote, urlparse, urlunparse from redisvl.redis.constants import REDIS_URL_ENV_VAR -from redisvl.utils.log import _has_application_handlers, get_logger +from redisvl.utils.log import get_logger logger = get_logger("[RedisVL]") DEFAULT_REDIS_HOST = "localhost" DEFAULT_REDIS_PORT = 6379 -def log_cli_exception(exc: BaseException) -> None: - """Record a CLI failure when the host application configured logging.""" - if _has_application_handlers(logger.name): - logger.error(exc, exc_info=True) - - def _has_explicit_connection_options(args: Namespace) -> bool: return any( ( diff --git a/redisvl/utils/log.py b/redisvl/utils/log.py index 24c3605ae..8a4792c15 100644 --- a/redisvl/utils/log.py +++ b/redisvl/utils/log.py @@ -1,71 +1,10 @@ import logging -class _DefaultStderrHandler(logging.Handler): - """Emit WARNING+ when the application has not configured logging. - - ``NullHandler`` counts as a handler and prevents ``logging.lastResort`` - from running, which hid RedisVL warnings before #786. This handler forwards - WARNING and above to stderr (via ``lastResort``) when the root logger has - no handlers, and forwards to the root logger once logging is configured. - Exception tracebacks are not written here so CLI code can log with - ``exc_info`` for configured apps without duplicating tracebacks on stderr. - """ - - def __init__(self, logger_name: str) -> None: - super().__init__(level=logging.WARNING) - self._logger_name = logger_name - - def emit(self, record: logging.LogRecord) -> None: - if _has_application_handlers(record.name): - return - if _default_stderr_owner(record.name) != self._logger_name: - return - clean = logging.makeLogRecord( - { - **record.__dict__, - "exc_info": None, - "exc_text": None, - "stack_info": None, - } - ) - last_resort = logging.lastResort - if last_resort is not None: - last_resort.handle(clean) - - -def _default_stderr_owner(record_name: str) -> str | None: - """Logger name whose ``_DefaultStderrHandler`` should emit for ``record_name``.""" - parts = record_name.split(".") - owner: str | None = None - for i in range(1, len(parts) + 1): - candidate = ".".join(parts[:i]) - logger = logging.getLogger(candidate) - if any(isinstance(h, _DefaultStderrHandler) for h in logger.handlers): - owner = candidate - return owner - - -def _has_application_handlers(logger_name: str) -> bool: - """True when the host app attached handlers outside RedisVL's default.""" - root = logging.getLogger() - if root.handlers: - return True - parts = logger_name.split(".") - for i in range(len(parts), 0, -1): - for handler in logging.getLogger(".".join(parts[:i])).handlers: - if not isinstance(handler, _DefaultStderrHandler): - return True - return False - - def get_logger(name, log_level="info", fmt=None): """Return a logger instance.""" # Use file name if logger is in debug mode name = "RedisVL" if log_level == "debug" else name - logger = logging.getLogger(name) - if not any(isinstance(h, _DefaultStderrHandler) for h in logger.handlers): - logger.addHandler(_DefaultStderrHandler(name)) - return logger + return logging.getLogger(name) diff --git a/tests/unit/test_cli_index.py b/tests/unit/test_cli_index.py index 1522426e5..b38d7b39a 100644 --- a/tests/unit/test_cli_index.py +++ b/tests/unit/test_cli_index.py @@ -2,6 +2,7 @@ import re import subprocess import sys +import textwrap from types import SimpleNamespace from unittest.mock import MagicMock @@ -459,4 +460,33 @@ def test_index_runtime_errors( assert exc_info.value.code == 1 assert captured.out == "" assert captured.err != "" - assert "Traceback" not in captured.err + + +def test_index_failure_stderr_subprocess_has_no_traceback(): + """Unconfigured logging: ``rvl index`` failures print one line, no traceback.""" + result = subprocess.run( + [ + sys.executable, + "-c", + textwrap.dedent(""" + import sys + from unittest.mock import MagicMock, patch + + fake_index = MagicMock() + fake_index.info.side_effect = RuntimeError("boom") + with patch("redisvl.cli.index.SearchIndex", return_value=fake_index): + sys.argv = ["rvl", "index", "info", "-i", "test-idx"] + try: + from redisvl.cli.index import Index + Index() + except SystemExit as exc: + sys.exit(exc.code) + """), + ], + capture_output=True, + text=True, + check=False, + ) + assert result.returncode == 1, result.stderr + assert "boom" in result.stderr + assert "Traceback" not in result.stderr diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py index 124be544a..837d064f0 100644 --- a/tests/unit/test_log.py +++ b/tests/unit/test_log.py @@ -9,8 +9,6 @@ import sys import textwrap -from redisvl.utils.log import _DefaultStderrHandler, get_logger - def _run(script: str) -> subprocess.CompletedProcess[str]: return subprocess.run( @@ -21,112 +19,22 @@ def _run(script: str) -> subprocess.CompletedProcess[str]: ) -def _line_with(lines: list[str], message: str) -> str: - matched = [line for line in lines if message in line] - assert len(matched) == 1, lines - return matched[0] - - -def _same_handler_format(left: str, right: str) -> None: - """Both lines come from the same handler when only name and message differ.""" - - def normalize(line: str, name: str, message: str) -> str: - return line.replace(name, "NAME", 1).replace(message, "MSG", 1) - - assert normalize(left, "redisvl.demo", "from redisvl logger") == normalize( - right, "plain.demo", "from plain logger" - ) - - -def test_get_logger_attaches_default_stderr_handler(): - name = "redisvl.test.stderr_handler" - logger = get_logger(name) - assert len(logger.handlers) == 1 - assert isinstance(logger.handlers[0], _DefaultStderrHandler) - assert logger.propagate is True - - -def test_warning_reaches_stderr_without_logging_configuration(): +def test_warning_reaches_stderr_when_logging_is_unconfigured(): result = _run(""" import logging from redisvl.utils.log import get_logger - logger = get_logger("redisvl.demo") - logger.info("redisvl info hidden") - logger.warning("from redisvl logger") - logger.error("from redisvl error") + get_logger("redisvl.demo").info("redisvl info hidden") + get_logger("redisvl.demo").warning("from redisvl logger") logging.getLogger("plain.demo").warning("from plain logger") """) assert result.returncode == 0, result.stderr assert "redisvl info hidden" not in result.stderr - stderr_lines = result.stderr.splitlines() - redis_line = _line_with(stderr_lines, "from redisvl logger") - _line_with(stderr_lines, "from redisvl error") - plain_line = _line_with(stderr_lines, "from plain logger") - _same_handler_format(redis_line, plain_line) - - -def test_error_with_exc_info_does_not_write_traceback_to_stderr(): - result = _run(""" - from redisvl.utils.log import get_logger - - logger = get_logger("redisvl.cli.test") - try: - raise RuntimeError("cli failure") - except RuntimeError as exc: - logger.error(exc, exc_info=True) - """) - assert result.returncode == 0, result.stderr - assert "cli failure" in result.stderr - assert "Traceback" not in result.stderr - - -def test_info_propagates_when_root_logging_is_configured_for_debug(): - result = _run(""" - import logging - import sys - - logging.basicConfig( - stream=sys.stdout, - format="APP %(levelname)s %(name)s %(message)s", - level=logging.DEBUG, - ) - from redisvl.utils.log import get_logger - - get_logger("redisvl.demo").info("configured redisvl info") - """) - assert result.returncode == 0, result.stderr - assert result.stdout.splitlines() == [ - "APP INFO redisvl.demo configured redisvl info" - ] - assert "configured redisvl info" not in result.stderr - - -def test_parent_logger_handlers_receive_redisvl_records(): - result = _run(""" - import logging - import sys - - parent = logging.getLogger("redisvl") - parent.setLevel(logging.INFO) - parent.addHandler( - logging.StreamHandler(sys.stdout) - ) - parent.handlers[0].setFormatter( - logging.Formatter("PARENT %(levelname)s %(name)s %(message)s") - ) - from redisvl.utils.log import get_logger - - get_logger("redisvl.demo").info("parent handler info") - """) - assert result.returncode == 0, result.stderr - assert result.stdout.splitlines() == [ - "PARENT INFO redisvl.demo parent handler info" - ] - assert "parent handler info" not in result.stderr + assert "from redisvl logger" in result.stderr + assert "from plain logger" in result.stderr -def test_configured_logging_still_receives_redisvl_warnings(): +def test_configured_logging_receives_warning_exactly_once(): result = _run(""" import logging import sys @@ -145,27 +53,3 @@ def test_configured_logging_still_receives_redisvl_warnings(): "APP WARNING redisvl.demo configured redisvl warning" ] assert "configured redisvl warning" not in result.stderr - - -def test_parent_and_child_default_handlers_do_not_duplicate_stderr(): - result = _run(""" - from redisvl.utils.log import get_logger - - get_logger("redisvl") - get_logger("redisvl.demo").warning("single parent child warning") - """) - assert result.returncode == 0, result.stderr - _line_with(result.stderr.splitlines(), "single parent child warning") - - -def test_warning_emit_succeeds_when_last_resort_is_none(): - result = _run(""" - import logging - from redisvl.utils.log import get_logger - - logging.lastResort = None - get_logger("redisvl.demo").warning("suppressed by none last resort") - """) - assert result.returncode == 0, result.stderr - assert "suppressed by none last resort" not in result.stderr - assert "Traceback" not in result.stderr