refactor(search): address PR #750 round 8 review feedback

- Rename `verified_count` → `verified_chunk_count` to make the count
  granularity explicit at the field name (chunks vs unique docs).
- News verifier now fails open *per-item* on non-numeric stored doc_ids
  (matches notes/files/deck shape); a single bad id no longer rescues
  definitively-missing siblings from eviction.
- Update note-verifier integration test to use string doc_ids end-to-end
  to match production storage (scanner.py:241 stringifies note ids).
- Add regression test for the closed-task-group race guard in
  `verify_search_results` so the RuntimeError swallow is locked in.
- Convert remaining f-string logger calls in `server/semantic.py` to
  lazy %-style formatting (per repo convention).
- Document `evict_on_missing` as a developer/test flag (no env var) and
  flag the `get_file_info` 404→raise contract change in its docstring.
- Add a TODO(ADR-019) breadcrumb for the hardcoded 2× over-fetch so
  future tuning has a clear hook.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Chris Coutinho
2026-05-01 21:40:30 +02:00
co-authored by Claude Opus 4.7
parent 3e981e647a
commit 8a2626da6c
6 changed files with 252 additions and 76 deletions
+5 -3
View File
@@ -513,9 +513,11 @@ aware of:
(fail open) so a flaky link does not silently shrink result pages; only
*definitive* 404 / 403 drops them.
If verification ever needs to be disabled (debugging, benchmarking), the
`evict_on_missing=False` flag on `verify_search_results()` skips eviction
without changing what is returned to the caller.
If eviction ever needs to be disabled (debugging, benchmarking), the
`evict_on_missing=False` keyword argument on `verify_search_results()` skips
the Qdrant deletes without changing what is returned to the caller. **This
is a developer/test flag, not an operator knob — it has no env-var
equivalent.** Operators who need a runtime toggle should open an issue.
### Environment Variables Reference
+9
View File
@@ -1301,6 +1301,15 @@ class WebDAVClient(BaseNextcloudClient):
async def get_file_info(self, path: str) -> dict[str, Any] | None:
"""Get file info including file ID via WebDAV PROPFIND.
.. note::
**Behavior change (ADR-019):** previously this method returned
``None`` for HTTP 404. It now raises ``HTTPStatusError`` for any
non-2xx status, including 404. ``None`` is reserved for the
ambiguous *malformed PROPFIND* case (server returned 2xx with a
response body missing required XML elements). External callers
updating from the old contract must catch ``HTTPStatusError``
and inspect ``e.response.status_code`` to handle 404 explicitly.
Args:
path: Path to the file (relative to user's files directory)
+4 -6
View File
@@ -80,16 +80,14 @@ class SemanticSearchResponse(BaseResponse):
search_method: str = Field(
default="semantic", description="Search method used (semantic or hybrid)"
)
verified_count: int = Field(
verified_chunk_count: int = Field(
default=0,
description=(
"Number of search result chunks that passed verify-on-read "
"access checks (ADR-019). Equals len(verified_results) before "
"trimming to limit. Note: multiple chunks of the same document "
"are counted separately here, whereas dropped_count counts "
"unique (doc_id, doc_type) pairs — the asymmetry is intentional "
"(verified_count is sized in result rows, dropped_count is "
"sized in unique ghost documents)."
"trimming to limit. Sized in chunks (result rows), NOT in "
"unique documents — pair with dropped_count carefully: "
"dropped_count is sized in unique (doc_id, doc_type) pairs."
),
)
dropped_count: int = Field(
+17 -11
View File
@@ -323,28 +323,34 @@ async def _verify_news_items(
)
return set(doc_ids)
# Cast safely: a non-numeric id from the API or in our doc_ids would
# otherwise raise ValueError after the semaphore block exits and surface
# as a verifier crash. Treat as transient (fail open) instead.
# Build present_ids from the API response. If the API itself returns
# malformed (non-numeric) ids, the whole batch becomes unverifiable —
# fail open for every requested doc_id (transient).
try:
present_ids = {
int(item.get("id")) for item in items if item.get("id") is not None
}
# Map back to the original doc_id types (caller may pass ints or strs).
accessible: set[int | str] = set()
for d in doc_ids:
if int(d) in present_ids:
accessible.add(d)
return accessible
except (TypeError, ValueError) as e:
logger.warning(
"Non-numeric id while verifying news items (sample=%r, doc_ids=%r): %s; keeping all results",
"Non-numeric id in news API response (sample=%r): %s; keeping all results",
items[:3] if items else items,
doc_ids,
e,
)
return set(doc_ids)
# Per-item check: a single non-numeric *stored* doc_id is fail-open
# for THAT item only — not the whole batch. Mirrors the per-item
# shape of the notes/files/deck verifiers.
accessible: set[int | str] = set()
for d in doc_ids:
try:
if int(d) in present_ids:
accessible.add(d)
except (TypeError, ValueError):
logger.debug("Non-numeric news doc_id %r; keeping (cannot verify)", d)
accessible.add(d)
return accessible
_VERIFIERS: dict[str, BatchVerifier] = {
"note": _verify_notes,
+75 -41
View File
@@ -94,8 +94,13 @@ def configure_semantic_tools(mcp: FastMCP):
username = client.username
logger.info(
f"BM25 hybrid search: query='{query}', user={username}, "
f"limit={limit}, score_threshold={score_threshold}, fusion={fusion}"
"BM25 hybrid search: query=%r, user=%s, "
"limit=%d, score_threshold=%s, fusion=%s",
query,
username,
limit,
score_threshold,
fusion,
)
# Check that vector sync is enabled
@@ -130,6 +135,9 @@ def configure_semantic_tools(mcp: FastMCP):
# The 2× factor is a deliberate v1 trade-off — raising it
# costs Nextcloud round-trips on every search. Trim to
# ``limit`` happens AFTER verification.
# TODO(ADR-019): expose VERIFICATION_OVERFETCH so operators
# with persistent high ghost density can tune this without a
# code change.
unverified_results = await search_algo.search(
query=query,
user_id=username,
@@ -177,7 +185,7 @@ def configure_semantic_tools(mcp: FastMCP):
all_results,
eviction_task_group=eviction_task_group,
)
verified_count = len(verified_results)
verified_chunk_count = len(verified_results)
search_results = verified_results[:limit]
# Convert SearchResult objects to SemanticSearchResult for response.
@@ -227,8 +235,9 @@ def configure_semantic_tools(mcp: FastMCP):
# Expand results with surrounding context if requested
if include_context and results:
logger.info(
f"Expanding {len(results)} results with context "
f"(context_chars={context_chars})"
"Expanding %d results with context (context_chars=%d)",
len(results),
context_chars,
)
# Fetch context for all results in parallel
@@ -286,20 +295,27 @@ def configure_semantic_tools(mcp: FastMCP):
has_after_truncation=chunk_context.has_after_truncation,
)
logger.debug(
f"Expanded context for {result.doc_type} {result.id}"
"Expanded context for %s %s",
result.doc_type,
result.id,
)
else:
# Context expansion failed, keep original result
expanded_results[index] = result
logger.debug(
f"Failed to expand context for {result.doc_type} {result.id}, "
"keeping original result"
"Failed to expand context for %s %s, "
"keeping original result",
result.doc_type,
result.id,
)
except Exception as e:
# Context expansion failed, keep original result
expanded_results[index] = result
logger.warning(
f"Error expanding context for {result.doc_type} {result.id}: {e}"
"Error expanding context for %s %s: %s",
result.doc_type,
result.id,
e,
)
# Run all context fetches in parallel using anyio task group
@@ -310,17 +326,18 @@ def configure_semantic_tools(mcp: FastMCP):
# Replace results with expanded versions
results = [r for r in expanded_results if r is not None]
logger.info(
f"Context expansion completed: {len(results)} results with context"
"Context expansion completed: %d results with context",
len(results),
)
logger.info(f"Returning {len(results)} results from BM25 hybrid search")
logger.info("Returning %d results from BM25 hybrid search", len(results))
return SemanticSearchResponse(
results=results,
query=query,
total_found=len(results),
search_method=f"bm25_hybrid_{fusion}",
verified_count=verified_count,
verified_chunk_count=verified_chunk_count,
dropped_count=dropped_count,
)
@@ -341,7 +358,7 @@ def configure_semantic_tools(mcp: FastMCP):
ErrorData(code=-1, message=f"Network error during search: {str(e)}")
)
except Exception as e:
logger.error(f"Search error: {e}", exc_info=True)
logger.error("Search error: %s", e, exc_info=True)
raise McpError(ErrorData(code=-1, message=f"Search failed: {str(e)}"))
@mcp.tool(
@@ -422,7 +439,7 @@ def configure_semantic_tools(mcp: FastMCP):
# 2. Handle no results case - don't waste a sampling call
if not search_response.results:
logger.debug(f"No documents found for query: {query}")
logger.debug("No documents found for query: %r", query)
return SamplingSearchResponse(
query=query,
generated_answer="No relevant documents found in your Nextcloud content for this query.",
@@ -439,22 +456,25 @@ def configure_semantic_tools(mcp: FastMCP):
# Log capability check result for debugging
logger.info(
f"Sampling capability check: client_has_sampling={client_has_sampling}, "
f"query='{query}'"
"Sampling capability check: client_has_sampling=%s, query=%r",
client_has_sampling,
query,
)
if hasattr(ctx.session, "_client_params") and ctx.session._client_params:
client_caps = ctx.session._client_params.capabilities
logger.debug(
f"Client advertised capabilities: "
f"roots={client_caps.roots is not None}, "
f"sampling={client_caps.sampling is not None}, "
f"experimental={client_caps.experimental is not None}"
"Client advertised capabilities: "
"roots=%s, sampling=%s, experimental=%s",
client_caps.roots is not None,
client_caps.sampling is not None,
client_caps.experimental is not None,
)
if not client_has_sampling:
logger.info(
f"Client does not support sampling (query: '{query}'), "
f"returning {len(search_response.results)} documents"
"Client does not support sampling (query: %r), returning %d documents",
query,
len(search_response.results),
)
return SamplingSearchResponse(
query=query,
@@ -493,8 +513,9 @@ def configure_semantic_tools(mcp: FastMCP):
accessible_results[index] = result
full_contents[index] = content
logger.debug(
f"Fetched full content for note {result.id} "
f"(length: {len(content)} chars)"
"Fetched full content for note %s (length: %d chars)",
result.id,
len(content),
)
except Exception as e:
# Race window after verify_search_results — drop result.
@@ -524,7 +545,9 @@ def configure_semantic_tools(mcp: FastMCP):
# Check if we filtered out all results
if not accessible_results:
logger.warning(f"All search results became inaccessible for query: {query}")
logger.warning(
"All search results became inaccessible for query: %r", query
)
return SamplingSearchResponse(
query=query,
generated_answer="All matching documents are no longer accessible.",
@@ -566,9 +589,12 @@ def configure_semantic_tools(mcp: FastMCP):
)
logger.info(
f"Initiating sampling request: query_length={len(query)}, "
f"documents={len(search_response.results)}, "
f"prompt_length={len(prompt)}, max_tokens={max_answer_tokens}"
"Initiating sampling request: query_length=%d, documents=%d, "
"prompt_length=%d, max_tokens=%d",
len(query),
len(search_response.results),
len(prompt),
max_answer_tokens,
)
# 6. Request LLM completion via MCP sampling with timeout
@@ -601,13 +627,15 @@ def configure_semantic_tools(mcp: FastMCP):
# Handle non-text responses (shouldn't happen for text prompts)
generated_answer = f"Received non-text response of type: {sampling_result.content.type}"
logger.warning(
f"Unexpected content type from sampling: {sampling_result.content.type}"
"Unexpected content type from sampling: %s",
sampling_result.content.type,
)
logger.info(
f"Sampling successful: model={sampling_result.model}, "
f"stop_reason={sampling_result.stopReason}, "
f"answer_length={len(generated_answer)}"
"Sampling successful: model=%s, stop_reason=%s, answer_length=%d",
sampling_result.model,
sampling_result.stopReason,
len(generated_answer),
)
return SamplingSearchResponse(
@@ -623,8 +651,10 @@ def configure_semantic_tools(mcp: FastMCP):
except TimeoutError:
logger.warning(
f"Sampling request timed out after {sampling_timeout_seconds} seconds for query: '{query}', "
f"returning search results only"
"Sampling request timed out after %d seconds for query: %r, "
"returning search results only",
sampling_timeout_seconds,
query,
)
return SamplingSearchResponse(
query=query,
@@ -646,18 +676,20 @@ def configure_semantic_tools(mcp: FastMCP):
if "rejected" in error_msg.lower() or "denied" in error_msg.lower():
# User explicitly declined - this is normal, not an error
logger.info(f"User declined sampling request for query: '{query}'")
logger.info("User declined sampling request for query: %r", query)
search_method = "semantic_sampling_user_declined"
user_message = "User declined to generate an answer"
elif "not supported" in error_msg.lower():
# Client doesn't support sampling - also normal
logger.info(f"Sampling not supported by client for query: '{query}'")
logger.info("Sampling not supported by client for query: %r", query)
search_method = "semantic_sampling_unsupported"
user_message = "Sampling not supported by this client"
else:
# Other MCP protocol errors
logger.warning(
f"MCP error during sampling for query '{query}': {error_msg}"
"MCP error during sampling for query %r: %s",
query,
error_msg,
)
search_method = "semantic_sampling_mcp_error"
user_message = f"Sampling unavailable: {error_msg}"
@@ -678,8 +710,10 @@ def configure_semantic_tools(mcp: FastMCP):
except Exception as e:
# Truly unexpected errors - these SHOULD have tracebacks
logger.error(
f"Unexpected error during sampling for query '{query}': "
f"{type(e).__name__}: {e}",
"Unexpected error during sampling for query %r: %s: %s",
query,
type(e).__name__,
e,
exc_info=True,
)
@@ -763,7 +797,7 @@ def configure_semantic_tools(mcp: FastMCP):
indexed_count = count_result.count
except Exception as e:
logger.warning(f"Failed to query Qdrant for indexed count: {e}")
logger.warning("Failed to query Qdrant for indexed count: %s", e)
# Continue with indexed_count = 0
# Determine status
@@ -777,7 +811,7 @@ def configure_semantic_tools(mcp: FastMCP):
)
except Exception as e:
logger.error(f"Error getting vector sync status: {e}")
logger.error("Error getting vector sync status: %s", e)
raise McpError(
ErrorData(
code=-1,
+142 -15
View File
@@ -178,6 +178,29 @@ async def test_verify_notes_mixed_outcomes(mocker):
assert result == {1, 3}
@pytest.mark.unit
async def test_verify_notes_string_doc_id_matches_production(mocker):
"""Notes are stored with string doc_ids in production (scanner.py:241).
The verifier must parse the string to int for the API call but
preserve the original string in the accessible set so eviction
receives the same type that was indexed in Qdrant. Without this
contract, a `MatchValue(value=42)` eviction filter would not match
a payload stored as `"42"`.
"""
notes_client = SimpleNamespace(
get_note=mocker.AsyncMock(return_value={"id": 42, "content": "x"})
)
client = SimpleNamespace(notes=notes_client, username="alice")
result = await _verify_notes(client, [_make_result("42", doc_type="note")], _sem())
# Original string id is preserved (not coerced to int 42).
assert result == {"42"}
# The API call still uses the int form internally.
notes_client.get_note.assert_awaited_once_with(42)
# ---------------------------------------------------------------------------
# News batch verifier
# ---------------------------------------------------------------------------
@@ -267,15 +290,15 @@ async def test_verify_news_items_transient_keeps_all(mocker):
@pytest.mark.unit
async def test_verify_news_items_non_numeric_id_keeps_all(mocker):
"""One non-numeric doc_id triggers fail-open for the WHOLE result set.
async def test_verify_news_items_non_numeric_id_keeps_only_bad_item(mocker):
"""A non-numeric doc_id is fail-open per item, not per batch.
The intersection logic in `_verify_news_items` tries `int(d)` for each
incoming doc_id; a single non-numeric value (e.g. ``"abc"``) raises
ValueError inside the intersection loop. The except block must catch it
and return the full input set (fail open) rather than dropping anything.
This is intentional v1 behaviour — surfacing one bad id should not
drop legitimate adjacent results.
incoming doc_id; a single non-numeric value (e.g. ``"abc"``) is now
caught per-item — only that one id is preserved unverified, while
valid numeric ids are still checked against the API response. Mirrors
the per-item shape of the notes/files/deck verifiers (one bad id does
not poison adjacent verifications).
"""
news_client = SimpleNamespace(
get_items=mocker.AsyncMock(return_value=[{"id": 10}, {"id": 20}])
@@ -289,10 +312,59 @@ async def test_verify_news_items_non_numeric_id_keeps_all(mocker):
_sem(),
)
# Fail-open: every requested id is preserved, INCLUDING the bad one.
# 10 and 20 are verified present; "abc" is unverifiable so kept fail-open.
assert result == {10, 20, "abc"}
@pytest.mark.unit
async def test_verify_news_items_drops_missing_when_other_id_is_non_numeric(
mocker,
):
"""A non-numeric doc_id no longer rescues a definitively-missing id.
Regression for the per-item fail-open: previously a single non-numeric
doc_id triggered batch-wide fail-open, so a definitively-missing id
(20 below) escaped eviction. With per-item handling, only "abc" is
kept; 20 is correctly dropped.
"""
news_client = SimpleNamespace(get_items=mocker.AsyncMock(return_value=[{"id": 10}]))
client = SimpleNamespace(news=news_client, username="alice")
doc_ids: list[int | str] = [10, 20, "abc"]
result = await _verify_news_items(
client,
[_make_result(d, doc_type="news_item") for d in doc_ids],
_sem(),
)
# 10 verified present, 20 verified missing (dropped), "abc" unverifiable.
assert result == {10, "abc"}
@pytest.mark.unit
async def test_verify_news_items_malformed_api_response_keeps_all(mocker):
"""A malformed API response (non-numeric server id) fails open per batch.
Distinct from a non-numeric *stored* doc_id: when the News API itself
returns garbage, we cannot build present_ids at all, so every requested
doc_id is preserved (transient — eviction will retry on next query).
"""
news_client = SimpleNamespace(
get_items=mocker.AsyncMock(return_value=[{"id": "not-an-int"}, {"id": 20}])
)
client = SimpleNamespace(news=news_client, username="alice")
doc_ids: list[int | str] = [10, 20]
result = await _verify_news_items(
client,
[_make_result(d, doc_type="news_item") for d in doc_ids],
_sem(),
)
# Batch fail-open: API broken, every requested id preserved.
assert result == {10, 20}
# ---------------------------------------------------------------------------
# File verifier
# ---------------------------------------------------------------------------
@@ -531,25 +603,32 @@ async def test_verify_search_results_dedupes_chunks_per_document(mocker):
@pytest.mark.unit
async def test_verify_search_results_drops_inaccessible_and_evicts(mocker):
"""Inline-fallback path (no eviction_task_group): evict completes before return."""
"""Inline-fallback path (no eviction_task_group): evict completes before return.
Notes are stored with string doc_ids in production (scanner.py:241
``doc_id = str(note["id"])``), so this test uses string ids end-to-end
to exercise the actual production type — ``SearchResult.id``,
``_VERIFIERS["note"]`` return-set members, and
``delete_document_points`` arguments all stay as ``str``.
"""
spy_evict = mocker.AsyncMock()
mocker.patch.object(verification, "delete_document_points", spy_evict)
# Verifier reports note 1 accessible, note 99 not
note_verifier = mocker.AsyncMock(return_value={1})
# Verifier reports note "1" accessible, note "99" not
note_verifier = mocker.AsyncMock(return_value={"1"})
mocker.patch.dict(verification._VERIFIERS, {"note": note_verifier}, clear=False)
results = [
_make_result(1, doc_type="note"),
_make_result(99, doc_type="note"),
_make_result("1", doc_type="note"),
_make_result("99", doc_type="note"),
]
client = SimpleNamespace(username="alice")
kept, dropped_count = await verify_search_results(client, results)
assert [r.id for r in kept] == [1]
assert [r.id for r in kept] == ["1"]
assert dropped_count == 1
spy_evict.assert_awaited_once_with(99, "note", "alice")
spy_evict.assert_awaited_once_with("99", "note", "alice")
@pytest.mark.unit
@@ -598,6 +677,54 @@ async def test_verify_search_results_fire_and_forget_eviction(mocker):
assert eviction_completed.is_set()
@pytest.mark.unit
async def test_verify_search_results_eviction_task_group_closed_is_ignored(
mocker,
):
"""A closed eviction task group must not surface as a search error.
Guards the race documented in `verification.py`: the lifespan task
group can exit between the ``getattr()`` capture in
``server/semantic.py`` and the ``start_soon`` call here. Calling
``start_soon`` on a closed group raises ``RuntimeError``; the
verifier must catch and log it (eviction is best-effort, the next
query re-verifies). Without this guard the search response would
fail.
"""
spy_evict = mocker.AsyncMock()
mocker.patch.object(verification, "delete_document_points", spy_evict)
note_verifier = mocker.AsyncMock(return_value=set()) # 99 inaccessible
mocker.patch.dict(verification._VERIFIERS, {"note": note_verifier}, clear=False)
class ClosedTaskGroup:
"""Stand-in for an exited anyio.TaskGroup."""
def __init__(self):
self.start_soon_calls = 0
def start_soon(self, *_args, **_kwargs):
self.start_soon_calls += 1
raise RuntimeError("This task group is not active")
closed_tg = ClosedTaskGroup()
results = [_make_result(99, doc_type="note")]
client = SimpleNamespace(username="alice")
# Must NOT raise even though start_soon raises RuntimeError.
kept, dropped_count = await verify_search_results(
client, results, eviction_task_group=closed_tg
)
assert kept == []
assert dropped_count == 1
assert closed_tg.start_soon_calls == 1
# Inline fallback must NOT run when a (closed) task group was provided —
# the guard is fire-and-forget, eviction is dropped on the floor.
spy_evict.assert_not_awaited()
@pytest.mark.unit
async def test_verify_search_results_no_eviction_when_disabled(mocker):
spy_evict = mocker.AsyncMock()