diff --git a/src/documents/search/_query.py b/src/documents/search/_query.py index 143287537..8a3c67b70 100644 --- a/src/documents/search/_query.py +++ b/src/documents/search/_query.py @@ -133,35 +133,6 @@ def _user_facing_emit_message(d: Diagnostic) -> str: return "The search query could not be executed." -# MISCONFIGURED reports a static configuration fact (the registry declares a -# field the schema does not carry, or one that is not fast), so it stays true -# until an operator changes the schema and reindexes. The operator-facing log -# therefore fires once per (kind, field) per process: an alert that repeats on -# every user query is one operators learn to filter out. A restart re-logs, -# which re-surfaces the condition after a config change. -# -# Bounded by the registry, not by query text: emit() only reports MISCONFIGURED -# for a field it resolved, and FieldRegistry.resolve returns None for any name -# or JSON subpath the registry does not declare (those become AST_UNKNOWN_FIELD, -# an INTERNAL cause that never reaches here), so a user cannot grow this set. -_logged_misconfigurations: set[tuple[DiagnosticKind, str]] = set() - - -def _log_misconfiguration_once(d: Diagnostic) -> None: - """Log a registry/schema mismatch the first time this process sees it for - a given field. Never gates the 400: every request still gets its answer.""" - key = (d.kind, str(d.field)) - if key in _logged_misconfigurations: - return - _logged_misconfigurations.add(key) - logger.error( - "Search index misconfiguration for field %s (%s): %s", - d.field, - d.kind.name, - d.message, - ) - - def _map_emit_error(e: QueryError) -> SearchQueryError: """Route an emit-time QueryError by its Diagnostic's Cause. @@ -171,15 +142,19 @@ def _map_emit_error(e: QueryError) -> SearchQueryError: re-raised to surface the same way views.py already lets QueryParserError surface. MISCONFIGURED is deliberately both: the registry and the index schema disagree, which only an operator can fix, so it is logged as an - error (once per field per process, see _log_misconfiguration_once), but a - request is still waiting and the query cannot run either way, so it also - returns a 400. + error, but a request is still waiting and the query cannot run either + way, so it also returns a 400. """ d = e.diagnostic if d.cause is Cause.INTERNAL: raise e if d.cause is Cause.MISCONFIGURED: - _log_misconfiguration_once(d) + logger.error( + "Search index misconfiguration for field %s (%s): %s", + d.field, + d.kind.name, + d.message, + ) return SearchQueryError(_user_facing_emit_message(d)) diff --git a/src/documents/tests/search/test_error_routing.py b/src/documents/tests/search/test_error_routing.py index ba617ba2c..7864a089c 100644 --- a/src/documents/tests/search/test_error_routing.py +++ b/src/documents/tests/search/test_error_routing.py @@ -8,7 +8,6 @@ from __future__ import annotations import logging from datetime import UTC -from typing import TYPE_CHECKING import pytest import tantivy @@ -20,30 +19,17 @@ from whoosh_compat.fields import FieldKind from whoosh_compat.fields import FieldRef from documents.search._errors import SearchQueryError -from documents.search._query import _logged_misconfigurations from documents.search._query import _map_emit_error from documents.search._query import _single_diagnostic_to_error from documents.search._query import parse_user_query from documents.search._schema import build_schema from documents.search._tokenizer import register_tokenizers -if TYPE_CHECKING: - from collections.abc import Iterator - pytestmark = pytest.mark.search _LIBRARY_PROSE = "INTERNAL LIBRARY WORDING WITH raw tantivy detail" -@pytest.fixture(autouse=True) -def _forget_logged_misconfigurations() -> Iterator[None]: - """The MISCONFIGURED log dedupes per process, so each test starts from a - process that has never seen one.""" - _logged_misconfigurations.clear() - yield - _logged_misconfigurations.clear() - - @pytest.fixture(scope="module") def query_index() -> tantivy.Index: """An in-memory, unstemmed index; these tests only parse, never index.""" @@ -246,75 +232,3 @@ class TestRealQueriesRouteCorrectly: monkeypatch.setattr(query_mod, "tantivy_emit", raise_internal) with pytest.raises(QueryError): parse_user_query(query_index, "invoice", UTC) - - -class TestMisconfigurationLogIsDeduped: - """The operator alert fires once per field per process; the 400 never is. - - An alert that repeats on every user query is one operators filter out, - and EXISTS_REQUIRES_FAST is reachable from ordinary query text. - """ - - def test_repeated_query_logs_once_but_400s_every_time( - self, - query_index: tantivy.Index, - caplog: pytest.LogCaptureFixture, - ) -> None: - with caplog.at_level(logging.ERROR, logger="paperless.search"): - for _ in range(3): - with pytest.raises(SearchQueryError) as excinfo: - parse_user_query(query_index, "notes.user:*", UTC) - assert "notes.user" in str(excinfo.value) - assert len([r for r in caplog.records if r.levelno == logging.ERROR]) == 1 - - def test_a_different_field_still_logs( - self, - query_index: tantivy.Index, - caplog: pytest.LogCaptureFixture, - ) -> None: - """What stops a naive log-once-ever implementation passing.""" - with caplog.at_level(logging.ERROR, logger="paperless.search"): - for query in ("notes.user:*", "notes.user:*", "custom_fields.value:*"): - with pytest.raises(SearchQueryError): - parse_user_query(query_index, query, UTC) - logged = [r.getMessage() for r in caplog.records if r.levelno == logging.ERROR] - assert len(logged) == 2 - assert any("notes.user" in m for m in logged) - assert any("custom_fields.value" in m for m in logged) - - def test_the_same_field_under_a_different_kind_still_logs( - self, - caplog: pytest.LogCaptureFixture, - ) -> None: - """The key is (kind, field): two distinct misconfigurations of one - field are two distinct things for an operator to fix.""" - field = FieldRef("notes", "user") - with caplog.at_level(logging.ERROR, logger="paperless.search"): - for kind in ( - DiagnosticKind.EXISTS_REQUIRES_FAST, - DiagnosticKind.EXISTS_REQUIRES_FAST, - DiagnosticKind.SCHEMA_FIELD_MISSING, - ): - _map_emit_error( - QueryError( - _diagnostic(kind, field=field, field_kind=FieldKind.JSON), - ), - ) - assert len([r for r in caplog.records if r.levelno == logging.ERROR]) == 2 - - def test_the_dedupe_key_is_bounded_by_the_registry( - self, - query_index: tantivy.Index, - ) -> None: - """Query text cannot grow the set: a JSON subpath the registry does not - declare never resolves, so it never reaches the MISCONFIGURED branch - (it demotes to an unfielded text search instead).""" - for suffix in ("aaa", "bbb", "ccc"): - parse_user_query(query_index, f"notes.{suffix}:*", UTC) - assert _logged_misconfigurations == set() - - with pytest.raises(SearchQueryError): - parse_user_query(query_index, "notes.user:*", UTC) - assert _logged_misconfigurations == { - (DiagnosticKind.EXISTS_REQUIRES_FAST, "notes.user"), - }