diff --git a/docs/configuration.md b/docs/configuration.md index 1b4354c4..d31f40f8 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -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 diff --git a/nextcloud_mcp_server/client/webdav.py b/nextcloud_mcp_server/client/webdav.py index 0b314cb5..585cbc71 100644 --- a/nextcloud_mcp_server/client/webdav.py +++ b/nextcloud_mcp_server/client/webdav.py @@ -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) diff --git a/nextcloud_mcp_server/models/semantic.py b/nextcloud_mcp_server/models/semantic.py index b583b098..a2c713b7 100644 --- a/nextcloud_mcp_server/models/semantic.py +++ b/nextcloud_mcp_server/models/semantic.py @@ -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( diff --git a/nextcloud_mcp_server/search/verification.py b/nextcloud_mcp_server/search/verification.py index ced45d43..86456174 100644 --- a/nextcloud_mcp_server/search/verification.py +++ b/nextcloud_mcp_server/search/verification.py @@ -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, diff --git a/nextcloud_mcp_server/server/semantic.py b/nextcloud_mcp_server/server/semantic.py index 5ab53042..977851cc 100644 --- a/nextcloud_mcp_server/server/semantic.py +++ b/nextcloud_mcp_server/server/semantic.py @@ -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, diff --git a/tests/unit/search/test_verification.py b/tests/unit/search/test_verification.py index 46d40ce3..94612eca 100644 --- a/tests/unit/search/test_verification.py +++ b/tests/unit/search/test_verification.py @@ -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()