fix(search): stop logging an operator ERROR for field:* on a JSON field

_map_emit_error routed every MISCONFIGURED diagnostic to an ERROR log, so the
six user-typeable spellings of a JSON existence search (notes:*, notes.note:*,
notes.user:*, custom_fields:*, custom_fields.name:*, custom_fields.value:*)
each wrote one permanent ERROR line per request, and any authenticated user
could generate them in a loop.

Nothing is misconfigured. whoosh-compat decides EXISTS_REQUIRES_FAST from the
registry's own FieldSpec (kind plus fast) without consulting the index schema,
and field_descriptors() builds the JSON fields non-fast on purpose, so no
operator action can clear the condition. It is ordinary user error and now
gets the 400 with no alert. SCHEMA_FIELD_MISSING, the other MISCONFIGURED
kind, really is a registry-versus-schema comparison and keeps the ERROR.

The 400 and its user-facing message are unchanged. No log deduplication is
introduced; the classification is what was wrong, not the logging policy.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
stumpylog
2026-08-20 12:11:31 -07:00
co-authored by Claude Opus 5
parent 82546f13b3
commit 0d609074dd
3 changed files with 112 additions and 21 deletions
+13 -1
View File
@@ -67,11 +67,23 @@ def _map_emit_error(e: QueryError) -> SearchQueryError:
schema disagree, which only an operator can fix, so it is logged as an
error, but a request is still waiting and the query cannot run either
way, so it also returns a 400.
EXISTS_REQUIRES_FAST is the one MISCONFIGURED kind that is not a
disagreement. whoosh-compat derives it from the registry's own FieldSpec
(kind plus fast) without ever consulting the index schema, so it fires
whenever a non-fast field of a kind that cannot answer "exists" is asked
to: for us that is only the JSON fields, which field_descriptors() builds
non-fast on purpose. "notes:*" and the five other spellings of it are
ordinary user error that no operator action can clear, so they get the
400 without the alert.
"""
d = e.diagnostic
if d.cause is Cause.INTERNAL:
raise e
if d.cause is Cause.MISCONFIGURED:
if (
d.cause is Cause.MISCONFIGURED
and d.kind is not DiagnosticKind.EXISTS_REQUIRES_FAST
):
logger.error(
"Search index misconfiguration for field %s (%s): %s",
d.field,
@@ -74,18 +74,11 @@ class TestEmitErrorRouting:
_map_emit_error(error)
assert excinfo.value is error
@pytest.mark.parametrize(
"kind",
[
DiagnosticKind.SCHEMA_FIELD_MISSING,
DiagnosticKind.EXISTS_REQUIRES_FAST,
],
)
def test_misconfigured_cause_is_logged_and_becomes_a_400(
self,
kind: DiagnosticKind,
caplog: pytest.LogCaptureFixture,
) -> None:
kind = DiagnosticKind.SCHEMA_FIELD_MISSING
with caplog.at_level(logging.ERROR, logger="paperless.search"):
error = _map_emit_error(
QueryError(_diagnostic(kind, field=FieldRef("asn"))),
@@ -101,6 +94,7 @@ class TestEmitErrorRouting:
[
DiagnosticKind.TEXT_RANGE,
DiagnosticKind.PATTERN_TOO_COMPLEX,
DiagnosticKind.EXISTS_REQUIRES_FAST,
],
)
def test_unsupported_cause_is_a_400_with_no_operator_log(
@@ -109,7 +103,11 @@ class TestEmitErrorRouting:
caplog: pytest.LogCaptureFixture,
) -> None:
"""A query tantivy cannot run is the user's to fix; it must not page
an operator the way a registry/schema mismatch does."""
an operator the way a registry/schema mismatch does.
EXISTS_REQUIRES_FAST is nominally MISCONFIGURED but belongs here: it
is decided from the registry's own FieldSpec, so it never reports a
disagreement anyone could resolve."""
with caplog.at_level(logging.WARNING, logger="paperless.search"):
error = _map_emit_error(QueryError(_diagnostic(kind)))
assert isinstance(error, SearchQueryError)
@@ -198,17 +196,6 @@ class TestRealQueriesRouteCorrectly:
parse_user_query(query_index, "title:[a to b]", UTC)
assert "title" in str(excinfo.value)
def test_exists_on_a_non_fast_json_subpath_logs_and_400s(
self,
query_index: tantivy.Index,
caplog: pytest.LogCaptureFixture,
) -> None:
with caplog.at_level(logging.ERROR, logger="paperless.search"):
with pytest.raises(SearchQueryError) as excinfo:
parse_user_query(query_index, "notes.user:*", UTC)
assert "notes.user" in str(excinfo.value)
assert any(r.levelno == logging.ERROR for r in caplog.records)
def test_wildcard_on_a_numeric_field_is_a_400_naming_the_field(
self,
query_index: tantivy.Index,
@@ -0,0 +1,92 @@
"""``field:*`` on a JSON field is user error, not an operator alert.
whoosh-compat classifies EXISTS_REQUIRES_FAST as MISCONFIGURED, and
_map_emit_error used to route every MISCONFIGURED diagnostic to an ERROR log.
But the kind is decided from the registry's own FieldSpec (kind plus fast)
without consulting the index schema, and field_descriptors() builds the JSON
fields non-fast deliberately, so nothing is misconfigured and no operator
action can clear the condition. Any authenticated user could otherwise emit
ERROR lines in a loop by repeating ``notes:*``.
SCHEMA_FIELD_MISSING, the other MISCONFIGURED kind, does compare the registry
against the live schema, so it stays an ERROR.
"""
from __future__ import annotations
import logging
from datetime import UTC
import pytest
import tantivy
from whoosh_compat.errors import Diagnostic
from whoosh_compat.errors import DiagnosticKind
from whoosh_compat.errors import QueryError
from whoosh_compat.errors import cause_for
from whoosh_compat.fields import FieldKind
from whoosh_compat.fields import FieldRef
from documents.search._errors import SearchQueryError
from documents.search._query import _map_emit_error
from documents.search._query import parse_user_query
from documents.search._schema import build_schema
from documents.search._tokenizer import register_tokenizers
pytestmark = pytest.mark.search
# Every spelling of "does this JSON field have a value" a user can type.
EXISTS_QUERIES = [
"notes:*",
"notes.note:*",
"notes.user:*",
"custom_fields:*",
"custom_fields.name:*",
"custom_fields.value:*",
]
@pytest.fixture(scope="module")
def query_index() -> tantivy.Index:
idx = tantivy.Index(build_schema(), path=None)
register_tokenizers(idx, "")
return idx
class TestJsonExistsIsUserError:
@pytest.mark.parametrize("query", EXISTS_QUERIES)
def test_query_is_a_400_that_emits_no_error_log(
self,
query_index: tantivy.Index,
caplog: pytest.LogCaptureFixture,
query: str,
) -> None:
with caplog.at_level(logging.WARNING, logger="paperless.search"):
with pytest.raises(SearchQueryError) as excinfo:
parse_user_query(query_index, query, UTC)
assert query.split(":", maxsplit=1)[0] in str(excinfo.value)
assert [r for r in caplog.records if r.levelno >= logging.ERROR] == []
class TestGenuineMisconfigurationStillLogs:
def test_schema_field_missing_is_an_error_log(
self,
caplog: pytest.LogCaptureFixture,
) -> None:
"""The registry naming a field the index schema does not have is a
real mismatch an operator can fix, so it keeps the alert."""
kind = DiagnosticKind.SCHEMA_FIELD_MISSING
error = QueryError(
Diagnostic(
kind=kind,
cause=cause_for(kind),
message="field 'asn' is not defined in the index schema",
field=FieldRef("asn"),
field_kind=FieldKind.U64,
),
)
with caplog.at_level(logging.ERROR, logger="paperless.search"):
mapped = _map_emit_error(error)
assert isinstance(mapped, SearchQueryError)
records = [r for r in caplog.records if r.levelno == logging.ERROR]
assert len(records) == 1
assert kind.name in records[0].getMessage()