diff --git a/CACHING.md b/CACHING.md index b5cc434..2d85e6d 100644 --- a/CACHING.md +++ b/CACHING.md @@ -109,6 +109,30 @@ A warm that finishes without a complete result puts the term on a cooldown (`VFBQUERY_PREVIEW_WARM_COOLDOWN`, default 300s) so a term whose previews cannot be computed does not queue one warm per request and starve the terms that can. +**Fixed in v1.22.37:** the deferral above is only safe while it is *temporary*, +and it had stopped being temporary. `cache_result` wrote its documents with +`commit=false`, deferring visibility to the core's `autoSoftCommit` — but the +cache core is configured `autoSoftCommit.maxTime: -1` and +`autoCommit.openSearcher: false`, so no searcher ever reopens on its own. Writes +were durable and returned HTTP 200, yet nothing written could ever be read back. +Every request was therefore a cold miss, every cold miss took the fast path, and +every response carried `count: -1` — permanently, for every term. Writes now use +`commitWithin` (which this core *does* honour, with `softCommit: true`), so they +stay non-blocking but become searchable within ~10s +(`VFBQUERY_SOLR_COMMIT_WITHIN_MS`); `VFBQUERY_SOLR_WRITE_COMMIT=true` still +forces the old blocking hard commit. The same `commit=false` bug silently +disabled the expired-document delete, and is fixed alongside it. + +Two related changes went in with it. `preview_results` now carries an optional +`status` (`pending`/`complete`) and a `message` explaining what an unresolved +preview means and how to resolve it, because `count: -1` reads as "no results" +to anyone who has not read this page; absence of `status` keeps meaning +complete, since the cache holds three months of entries written without it. And +the read/write validators now ask `preview_is_resolved()` rather than testing +`count >= 0` directly, which incidentally fixes a term whose preview is complete +but whose exact total exceeded `COUNT_CAP`: its `count` is `-1` meaning "many", +and such a term was being rejected from cache and recomputed on every request. + ### Deliberately not cached - `get_similar_morphology_userdata` — keyed on a per-session user upload id; diff --git a/docs/http-api.md b/docs/http-api.md index 472eadf..d881081 100644 --- a/docs/http-api.md +++ b/docs/http-api.md @@ -62,6 +62,29 @@ GET /get_term_info?id=FBbt_00007401 | `id` | **Required.** A VFB short_form: `FBbt_…` (anatomy class), `VFB_…` (individual), `VFBexp_…`, `FBgn_…`, `FBlc_…`. | | `force_refresh` | `true` bypasses the result cache for this call. | +### Query previews may be pending + +Each entry in `Queries` carries a preview of that query's results. Computing all of them takes tens of +seconds on a cold term, so the first request for a term returns without them and warms them in the +background. Such a preview has empty `rows` and a **`count` of `-1`, which means *not counted* — not +zero.** It says nothing about whether results exist. + +`preview_results.status` names the state (`pending` or `complete`) and `preview_results.message` +explains it in a sentence. Both are optional and their **absence means complete**, because entries +cached before they existed carry neither; the fallback rule is `count >= 0`. A `complete` preview can +also carry `count: -1`, in the one case where `-1` means "many": the rows are final, but the exact +total exceeded the counting cap. Ask again shortly and a pending preview is usually filled in. + +### `X-Force-Refresh` + +`/get_term_info`, `/run_query` and `/query_connectivity` accept `X-Force-Refresh: true|1|yes|on` as a +header spelling of `force_refresh=true`. It exists because the `v3-cached` layer in front of this +service already defines that header as "bypass the edge cache and overwrite the cached entry with the +fresh upstream response", and reserves it for whitelisted callers. Sending the header refreshes both +layers in one request, at the URL users actually call. Adding `&force_refresh=true` instead does not: +the edge cache is keyed on the request URI, so the refreshed response lands in a *different* cache +entry and the one users hit is never healed. + ## `/run_query` ``` diff --git a/schema.md b/schema.md index 5d45763..8fb842e 100644 --- a/schema.md +++ b/schema.md @@ -5,6 +5,7 @@ This document describes the JSON schema structure for the Virtual Fly Brain (VFB ## Table of Contents - [Core Schema](#core-schema) + - [Query previews and the -1 count](#query-previews-and-the--1-count) - [Entity Types](#entity-types) - [Individual](#individual) - [Class](#class) @@ -51,6 +52,8 @@ The base schema returned by term info queries: "preview": "Integer (number of preview results, -1 for all)", "preview_columns": ["String (column identifiers)"], "preview_results": { + "status": "String (pending|complete; optional — absent means complete)", + "message": "String (present with status; explains a pending or uncounted preview)", "headers": { "column_id": { "title": "String (display name)", @@ -68,7 +71,7 @@ The base schema returned by term info queries: ] }, "output_format": "String (table/ribbon)", - "count": "Integer (total result count)" + "count": "Integer (total result count; -1 = not counted, distinct from 0)" } ], "IsIndividual": "Boolean", @@ -85,6 +88,34 @@ The base schema returned by term info queries: } ``` +### Query previews and the -1 count + +Each entry in `Queries` describes a query the caller can run against the term, and carries a small +preview of that query's results so a client can show something useful without running anything. A +preview is expensive, so it is not always available when the term itself is, and the schema has to be +able to say so. + +`count` is that signal. A count of `0` means the query was run and matched nothing. A count of `-1` +means the query has **not been counted**, which is a different statement entirely: it says nothing +about whether results exist, only that finding out requires running the query. Treating `-1` as "no +results" is the single most common misreading of this schema. (Note the unrelated `-1` on the +`preview` field just above it, which means "preview every result" — the two are not related.) + +A preview can be uncounted for four reasons. It has not been computed yet, because this was the first +request for the term and the full previews are being computed in the background; it timed out inside +its share of the response budget; it failed; or — the one case where `-1` does *not* mean unknown — +the rows are complete but the exact total exceeded the counting cap, so `-1` here means "many". + +`preview_results.status` distinguishes those. It is `pending` when the rows are not the answer and +`complete` when they are, and `preview_results.message` accompanies it with a sentence saying which +case this is and what to do about it. Both keys are optional, and **absence means complete**: results +cached before these keys existed carry neither, and remain valid. So the rule for a consumer is: +trust `status` when it is present, and fall back to `count >= 0` when it is not. + +A `pending` preview is transient, not an error. Requesting the same term again shortly will usually +return it filled in, since the first request schedules the computation; passing `force_refresh=true` +(or the `X-Force-Refresh: true` header, from a whitelisted caller) computes it synchronously instead. + ## Entity Types VFB entities fall into three main types, each with specific fields beyond the core schema: @@ -422,6 +453,7 @@ Finds individuals related to a template. "preview": 5, "preview_columns": ["id", "score", "name", "tags", "thumbnail"], "preview_results": { + "status": "complete", "headers": { "id": {"title": "Add", "type": "selection_id", "order": -1}, "score": {"title": "Score", "type": "numeric", "order": 1, "sort": {"0": "Desc"}}, @@ -554,6 +586,7 @@ Finds individuals related to a template. "preview": 5, "preview_columns": ["id", "name", "driver", "thumbnail"], "preview_results": { + "status": "complete", "headers": { "id": {"title": "Add", "type": "selection_id", "order": -1}, "name": {"title": "Name", "type": "markdown", "order": 1, "sort": {"0": "Asc"}}, diff --git a/src/vfbquery/_version.py b/src/vfbquery/_version.py index f3b1c11..47992b4 100644 --- a/src/vfbquery/_version.py +++ b/src/vfbquery/_version.py @@ -25,4 +25,4 @@ # Targeted invalidation, not a namespace flip. This is the documented exception, # not a licence to hand-manage the cache in general — the standing rule remains # force_refresh per call or a major.minor bump, never renaming buckets. -__version__ = "1.22.36" +__version__ = "1.22.37" diff --git a/src/vfbquery/cached_functions.py b/src/vfbquery/cached_functions.py index 36245f3..d603c12 100644 --- a/src/vfbquery/cached_functions.py +++ b/src/vfbquery/cached_functions.py @@ -6,7 +6,7 @@ """ from typing import Dict, Any, Optional -from .solr_result_cache import with_solr_cache +from .solr_result_cache import with_solr_cache, preview_is_resolved def is_valid_term_info_result(result): @@ -21,24 +21,23 @@ def is_valid_term_info_result(result): # Additional validation for query results if 'Queries' in result: for query in result['Queries']: - # Check if query has invalid count (-1) which indicates failed execution - # Note: count=0 is valid if preview_results structure is correct - count = query.get('count', 0) - # Check if preview_results has the correct structure preview_results = query.get('preview_results') if not isinstance(preview_results, dict): # print(f"DEBUG: Invalid preview_results type {type(preview_results)} detected") return False - + headers = preview_results.get('headers', []) if not headers: # print(f"DEBUG: Empty headers detected in preview_results") return False - - # Only reject if count is -1 (failed execution) or if count is 0 but preview_results is missing/empty - if count < 0: - # print(f"DEBUG: Invalid query count {count} detected") + + # Reject a preview that never resolved: count=0 is a valid answer + # ("no matches"), count=-1 is "not counted yet" and is not. A + # preview explicitly marked complete stays valid even at count -1, + # where -1 means "more than the counting cap" rather than "unknown". + if not preview_is_resolved(query): + # print(f"DEBUG: Unresolved query preview detected") return False return True diff --git a/src/vfbquery/ha_api.py b/src/vfbquery/ha_api.py index c051f31..bd262ec 100644 --- a/src/vfbquery/ha_api.py +++ b/src/vfbquery/ha_api.py @@ -930,12 +930,13 @@ async def handle_get_term_info(request): {"error": "Missing required parameter: id"}, status=400 ) - force_refresh = _query_flag(request, "force_refresh") + force_refresh = _force_refresh_requested(request) warnings = _unknown_param_warnings(request, _TERM_INFO_PARAMS) - warn = _flag_warning(request, "force_refresh") - if warn: - warnings.append(warn) + for warn in (_flag_warning(request, "force_refresh"), + _force_refresh_header_warning(request)): + if warn: + warnings.append(warn) def finish(result): return web.json_response(_with_warnings(result, warnings)) @@ -1114,6 +1115,43 @@ def _query_flag(request, name, default=False): return str(raw).strip().lower() in _TRUE_VALUES +#: Header spelling of ``force_refresh``. The v3-cached nginx layer in front of +#: this service already defines ``X-Force-Refresh: true|1|yes|on`` (from a +#: whitelisted IP) as "bypass the edge cache and overwrite the canonical slot +#: with a fresh upstream response". Until this service honoured it too, that +#: header refreshed the edge from an *unrefreshed* upstream — and the obvious +#: workaround, appending ``&force_refresh=true``, changes ``$request_uri`` and +#: therefore the nginx cache key, so it writes a different slot and can never +#: heal the canonical one. Accepting the header here closes that seam: one +#: request refreshes both layers, at the URL users actually call. +_FORCE_REFRESH_HEADER = "X-Force-Refresh" + + +def _force_refresh_requested(request): + """True when this request asks for a refresh, by query param or header. + + Either spelling is sufficient; neither overrides the other. + """ + if _query_flag(request, "force_refresh"): + return True + raw = request.headers.get(_FORCE_REFRESH_HEADER) + if raw is None: + return False + return str(raw).strip().lower() in _TRUE_VALUES + + +def _force_refresh_header_warning(request): + """Warn about an ``X-Force-Refresh`` value that is neither a yes nor a no.""" + raw = request.headers.get(_FORCE_REFRESH_HEADER) + if raw is None: + return None + value = str(raw).strip().lower() + if value in _TRUE_VALUES or value in _FALSE_VALUES: + return None + return ("%s: %r is not a recognised boolean and was read as false; use %s" + % (_FORCE_REFRESH_HEADER, str(raw), " / ".join(_TRUE_VALUES))) + + #: Spellings of "no" a caller might reasonably write for a flag. Everything #: outside these two sets is neither yes nor no — it is a typo, and #: :func:`_flag_warning` says so instead of quietly meaning "no". @@ -1338,13 +1376,16 @@ async def handle_run_query(request): ) include_graph = _query_flag(request, "include_graph") - force_refresh = _query_flag(request, "force_refresh") + force_refresh = _force_refresh_requested(request) warnings = _unknown_param_warnings(request, _RUN_QUERY_PARAMS) for flag in ("include_graph", "force_refresh"): warn = _flag_warning(request, flag) if warn: warnings.append(warn) + warn = _force_refresh_header_warning(request) + if warn: + warnings.append(warn) # `include_graph` is honoured by four of the forty query types. Asking for # it on any of the other thirty-six used to return a graphless result that @@ -1992,7 +2033,7 @@ async def handle_query_connectivity(request): from .vfb_connectivity import DEFAULT_EXCLUDE_DBS exclude_dbs = list(DEFAULT_EXCLUDE_DBS) include_graph = _query_flag(request, "include_graph") - force_refresh = _query_flag(request, "force_refresh") + force_refresh = _force_refresh_requested(request) # Resolved before the cache key is built, so `exclude_dbs=male-cns` and # `exclude_dbs=mc` share one entry instead of computing the same answer @@ -2013,6 +2054,9 @@ async def handle_query_connectivity(request): warn = _flag_warning(request, flag) if warn: warnings.append(warn) + warn = _force_refresh_header_warning(request) + if warn: + warnings.append(warn) def post_fn(result): if not isinstance(result, dict): diff --git a/src/vfbquery/solr_result_cache.py b/src/vfbquery/solr_result_cache.py index b258633..f2950aa 100644 --- a/src/vfbquery/solr_result_cache.py +++ b/src/vfbquery/solr_result_cache.py @@ -143,7 +143,86 @@ def cache_doc_glob(namespace: Optional[str] = None) -> str: return f"ns_{ns}{_NAMESPACE_SEPARATOR}vfb_query_*" if ns else "vfb_query_*" -@dataclass +#: ``preview_results.status`` values. ``pending`` means the query has not been +#: run for this term yet (or could not finish), so ``count`` is -1 = "not +#: counted", which is *not* the same as 0 = "no matches". ``complete`` means the +#: rows are final, even if ``count`` is -1 because the exact total exceeded the +#: counting cap. +#: +#: The key is optional and always has been: entries written before this shipped +#: carry no ``status``, and the cache holds three months of them. Absence +#: therefore has to keep meaning "complete" — see :func:`preview_is_resolved`. +PREVIEW_STATUS_PENDING = 'pending' +PREVIEW_STATUS_COMPLETE = 'complete' + + +def preview_is_resolved(query: Dict[str, Any]) -> bool: + """True when a query's preview holds a final answer. + + Prefers the explicit ``status`` and falls back to the ``count >= 0`` rule + for entries written before ``status`` existed. The fallback is the reason + this is a function rather than an inline comparison: read literally, + ``count < 0`` also condemns a *complete* preview whose total was capped, so + such a term could never be served from cache and was silently recomputed on + every request. + """ + preview_results = query.get('preview_results') + if not isinstance(preview_results, dict): + return False + status = preview_results.get('status') + if status == PREVIEW_STATUS_COMPLETE: + return True + if status == PREVIEW_STATUS_PENDING: + return False + return query.get('count', -1) >= 0 + + +# Default visibility delay for cache writes, in milliseconds. Ten seconds is +# comfortably inside the 3-month TTL and well under the time a cold term_info +# takes to recompute, so a write is readable long before anything would want to +# read it back. +_DEFAULT_COMMIT_WITHIN_MS = 10000 + + +def solr_write_params() -> Dict[str, str]: + """Update-handler params that make a write *visible*, without blocking on it. + + A per-write ``commit=true`` is a hard flush: it blocks the request until the + IndexWriter completes, and on a wedged writer (the soft-NFS ``write.lock`` + EIO failure mode) that stall propagates up — a cold-miss term such as a + License individual then hangs and saturates the ha_api worker queue, + surfacing as HTTP 503. So it is not the default. + + ``commit=false`` alone, however, is *not* a safe substitute here. It defers + to the core's own ``autoSoftCommit``, and the production cache core + (``vfb_json``) is configured with ``autoSoftCommit.maxTime: -1`` and + ``autoCommit.openSearcher: false`` — no searcher is ever reopened on its own. + Documents written that way are durable and the POST returns 200, but they + never become searchable, so every read-back misses and every call is cold. + That is what left ``get_term_info`` returning unresolved previews + (``count: -1``, ``rows: []``) indefinitely rather than transiently. + + ``commitWithin`` is the middle ground the core *does* honour (its + ``commitWithin`` is configured with ``softCommit: true``): the write returns + immediately, and Solr opens a new searcher within the given window, batching + concurrent writes into one flush. Override the window with + ``VFBQUERY_SOLR_COMMIT_WITHIN_MS``, or force the old blocking behaviour with + ``VFBQUERY_SOLR_WRITE_COMMIT=true``. + """ + if os.getenv('VFBQUERY_SOLR_WRITE_COMMIT', 'false').lower() in ('1', 'true', 'yes', 'on'): + return {"commit": "true"} + try: + within_ms = int(os.getenv('VFBQUERY_SOLR_COMMIT_WITHIN_MS', '') or _DEFAULT_COMMIT_WITHIN_MS) + except ValueError: + within_ms = _DEFAULT_COMMIT_WITHIN_MS + # A non-positive window would mean "never", reintroducing the invisible-write + # bug; clamp to the default instead. + if within_ms <= 0: + within_ms = _DEFAULT_COMMIT_WITHIN_MS + return {"commit": "false", "commitWithin": str(within_ms)} + + +@dataclass class CacheMetadata: """Metadata for cached results""" query_type: str # 'term_info', 'instances', etc. @@ -613,24 +692,15 @@ def cache_result(self, query_type: str, term_id: str, result: Any, **params) -> "expires_at": cached_data["expires_at"] } - # Store cache document. - # Use a soft (deferred) commit by default: a hard per-write - # ``commit=true`` flush blocks the request until the IndexWriter - # completes, and on a wedged writer (e.g. the soft-NFS write.lock - # EIO failure mode) that stall propagates up — a cold-miss term - # such as a License individual then hangs and saturates the ha_api - # worker queue, surfacing as HTTP 503. Relying on the core's - # autoSoftCommit (as the sibling write paths in this module already - # do) keeps the write fast and non-blocking; the 3-month cache - # tolerates a few seconds' visibility delay. Override with - # VFBQUERY_SOLR_WRITE_COMMIT=true if an immediate commit is needed. - commit_flag = os.getenv('VFBQUERY_SOLR_WRITE_COMMIT', 'false').lower() \ - in ('1', 'true', 'yes') + # Store cache document. ``solr_write_params()`` uses ``commitWithin`` + # so the write returns immediately but still becomes searchable — see + # that function for why a bare ``commit=false`` is never readable on + # this core. response = requests.post( f"{self.cache_url}/update", data=json.dumps([cache_doc]), headers={"Content-Type": "application/json"}, - params={"commit": "true" if commit_flag else "false"}, + params=solr_write_params(), timeout=int(os.getenv('VFBQUERY_SOLR_WRITE_TIMEOUT', '60')) ) @@ -668,7 +738,11 @@ def _clear_expired_cache_document(self, cache_doc_id: str): f"{self.cache_url}/update", data=f'{cache_doc_id}', headers={"Content-Type": "application/xml"}, - params={"commit": "false"}, # Don't commit immediately for performance + # Non-blocking, but still made visible: with a bare + # ``commit=false`` the delete never takes effect on a core + # without autoSoftCommit, so the expired document keeps being + # read back and re-expired on every subsequent lookup. + params=solr_write_params(), timeout=2 ) except Exception as e: @@ -1260,11 +1334,13 @@ def _call(*call_args, **call_kwargs): logger.debug(f"Query {i}: count={count}, preview_results_type={type(preview_results)}, headers={headers}") - # Check if query has error count (-1) which indicates failed execution - # Note: count of 0 is valid - it means "no matches found" - if count < 0: + # Reject a preview that never resolved. Note count + # of 0 is valid ("no matches found"), and so is + # count -1 on a preview explicitly marked + # complete (rows final, exact total capped). + if not preview_is_resolved(query): is_valid = False - logger.debug(f"Cached result has error query count {count} for {term_id}") + logger.debug(f"Cached result has unresolved query (count {count}) for {term_id}") break # Check if preview_results is missing or has empty headers when it should have data if not isinstance(preview_results, dict) or not headers: @@ -1461,11 +1537,10 @@ def _call(*call_args, **call_kwargs): failed_queries = 0 for query in result['Queries']: - count = query.get('count', -1) - preview_results = query.get('preview_results') - - # Count queries with valid results (count >= 0) - if count >= 0 and isinstance(preview_results, dict): + # Resolved = has a final answer; see + # preview_is_resolved for why this is not + # simply count >= 0. + if preview_is_resolved(query): valid_queries += 1 else: failed_queries += 1 diff --git a/src/vfbquery/vfb_queries.py b/src/vfbquery/vfb_queries.py index 48bd9ea..9b7a166 100644 --- a/src/vfbquery/vfb_queries.py +++ b/src/vfbquery/vfb_queries.py @@ -11,7 +11,9 @@ import numpy as np from urllib.parse import unquote import hashlib -from .solr_result_cache import with_solr_cache, solr_caching_disabled +from .solr_result_cache import (with_solr_cache, solr_caching_disabled, + PREVIEW_STATUS_PENDING, PREVIEW_STATUS_COMPLETE, + preview_is_resolved) import time import threading from concurrent.futures import ThreadPoolExecutor @@ -2485,16 +2487,64 @@ def _warming_previews(): return getattr(_bg_preview_state, 'warming', False) +#: ``count`` sentinel: not counted yet. Distinct from ``0`` ("no matches") — +#: see CACHING.md. It is deliberately *not* an error: the query simply has not +#: been run for this term, and running it is what resolves the number. +PREVIEW_COUNT_UNKNOWN = -1 + +#: Why a preview came back unresolved. The distinction matters to a caller +#: deciding what to do next: a not-yet-run preview resolves by asking again, +#: whereas a timeout resolves by running the query directly with its own budget. +PREVIEW_PENDING_NOT_RUN = ( + "This preview has not been computed yet, so count is -1 (not counted) " + "rather than 0 (no matches). The full results are being computed in the " + "background; request this term again shortly, or run the query directly " + "to get the results now.") + +PREVIEW_PENDING_TIMEOUT = ( + "This preview timed out before returning, so count is -1 (not counted) " + "rather than 0 (no matches). Run the query directly — on its own it has a " + "larger time budget than it gets as one preview among many.") + +PREVIEW_PENDING_ERROR = ( + "This preview could not be computed, so count is -1 (not counted) rather " + "than 0 (no matches). Run the query directly to get the results, or to see " + "the underlying error.") + +#: Rows are present and correct, but the total was too expensive to establish +#: exactly, so ``count`` is -1 meaning "more than the counting cap" rather than +#: "unknown". Only ``status`` separates this from a genuinely pending preview. +PREVIEW_COMPLETE_UNCOUNTED = ( + "Results are complete, but the total was not counted exactly: there are " + "more than {cap} matches, so count is -1 here meaning 'many', not " + "'unknown'.") + + +def _pending_preview(query, message): + """A ``preview_results`` block for a query whose results are not yet known. + + ``status``/``message`` are advisory and additive: a consumer that ignores + them still gets the long-standing contract (``count == -1``, empty + ``rows``). They exist because that contract is easy to misread as "no + results" — and because three months of cache entries written before this + shipped carry no ``status`` at all, so *absence* has to keep meaning + "complete" and cannot be used to signal anything. + """ + return { + 'status': PREVIEW_STATUS_PENDING, + 'message': message, + 'headers': query.get('preview_columns', ['id', 'label', 'tags', 'thumbnail']), + 'rows': [] + } + + def _blank_query_previews(term_info): """Return term_info with every query's preview left unresolved (count -1).""" for query in term_info.get('Queries', []): - query['preview_results'] = { - 'headers': query.get('preview_columns', ['id', 'label', 'tags', 'thumbnail']), - 'rows': [] - } + query['preview_results'] = _pending_preview(query, PREVIEW_PENDING_NOT_RUN) # -1 = not yet counted (distinct from a genuine 0), so the UI shows the # query as pending and the cache treats the entry as not-yet-complete. - query['count'] = -1 + query['count'] = PREVIEW_COUNT_UNKNOWN return term_info @@ -6873,14 +6923,14 @@ def process_query(query): f"reporting unknown count (-1) with empty preview") # Unknown, not empty: keep the query live so the user can run # it on demand; -1 distinguishes this from a known-empty (0). - query['preview_results'] = {'headers': query.get('preview_columns', ['id', 'label', 'tags', 'thumbnail']), 'rows': []} - query['count'] = -1 + query['preview_results'] = _pending_preview(query, PREVIEW_PENDING_TIMEOUT) + query['count'] = PREVIEW_COUNT_UNKNOWN return except Exception as e: print(f"Error executing query function {query['function']}: {e}") # Set default values for failed query (unknown count, not empty) - query['preview_results'] = {'headers': query.get('preview_columns', ['id', 'label', 'tags', 'thumbnail']), 'rows': []} - query['count'] = -1 + query['preview_results'] = _pending_preview(query, PREVIEW_PENDING_ERROR) + query['count'] = PREVIEW_COUNT_UNKNOWN return # print(f"Function result: {result}") @@ -6890,8 +6940,8 @@ def process_query(query): if result is None: print(f"ERROR: Query function {query['function']} returned None - this indicates a query failure that needs investigation") - query['preview_results'] = {'headers': query.get('preview_columns', ['id', 'label', 'tags', 'thumbnail']), 'rows': []} - query['count'] = -1 + query['preview_results'] = _pending_preview(query, PREVIEW_PENDING_ERROR) + query['count'] = PREVIEW_COUNT_UNKNOWN return if isinstance(result, dict) and 'rows' in result: @@ -7006,7 +7056,15 @@ def process_query(query): else: # Default to ID descending if no sort specified filtered_result.sort(key=lambda x: x.get('id', ''), reverse=True) - query['preview_results'] = {'headers': filtered_headers, 'rows': filtered_result} + query['preview_results'] = {'status': PREVIEW_STATUS_COMPLETE, + 'headers': filtered_headers, + 'rows': filtered_result} + if result_count == PREVIEW_COUNT_UNKNOWN: + # The rows are real; only the total is capped. Without this + # a consumer applying the "count < 0 means pending" rule + # would discard a perfectly good preview. + query['preview_results']['message'] = \ + PREVIEW_COMPLETE_UNCOUNTED.format(cap=COUNT_CAP) query['count'] = result_count # print(f"Filtered result: {filtered_result}") else: diff --git a/tests/test_force_refresh_header.py b/tests/test_force_refresh_header.py new file mode 100644 index 0000000..1a02465 --- /dev/null +++ b/tests/test_force_refresh_header.py @@ -0,0 +1,230 @@ +"""Regression tests: the refresh header the edge already speaks was ignored here. + +The nginx layer in front of this service (``v3-cached``) has long defined +``X-Force-Refresh: true`` — from a whitelisted IP — as "bypass the edge cache +and overwrite the canonical slot with a fresh upstream response". This service +read no request headers at all, so that header refreshed the edge *from an +unrefreshed upstream*: the operator got a 200, the edge dutifully stored it, and +the stale answer was re-canonicalised for another six months. + +The obvious workaround makes it worse rather than better. Appending +``&force_refresh=true`` does refresh this service, but it changes +``$request_uri`` and therefore the nginx cache key, so the fresh answer lands in +a *different* slot. The canonical URL — the one users actually call — can never +be healed that way, no matter how many times the refresh is run. + +Honouring the header here closes the seam: one request, from the whitelist, +refreshes both layers at the URL that matters. These tests drive the real +handler through a real aiohttp server and assert on the observable consequence +— whether the in-process L1 entry was dropped and the worker re-ran — rather +than on any internal flag. + +The app is assembled by hand rather than through ``create_app`` because that +starts a ``ProcessPoolExecutor`` whose initializer imports the entire query +stack. ``pool = None`` makes ``run_in_executor`` use the default thread pool, +which is all a stubbed worker needs. +""" +import asyncio + +import pytest +from aiohttp import web +from aiohttp.test_utils import TestClient, TestServer + +from conftest import run +from vfbquery import ha_api + + +def _make_app(): + app = web.Application() + app.router.add_get("/get_term_info", ha_api.handle_get_term_info) + + async def on_startup(app): + app["result_cache"] = ha_api.ResultCache(ttl_seconds=300) + app["coalescer"] = ha_api.RequestCoalescer() + app["tracker"] = ha_api.QueueTracker() + app["semaphore"] = asyncio.Semaphore(2) + app["pool"] = None # default executor; the worker is a stub + + app.on_startup.append(on_startup) + return app + + +def _stub_worker(monkeypatch): + """Replace the worker with one that counts runs and echoes force_refresh.""" + runs = [] + + def fake_run_term_info(short_form, force_refresh=False): + runs.append({"id": short_form, "force_refresh": force_refresh}) + return {"Name": short_form, "run": len(runs), + "saw_force_refresh": force_refresh} + + monkeypatch.setattr(ha_api, "_run_term_info", fake_run_term_info, + raising=True) + return runs + + +def _drive(headers_second=None, params_second=None): + """Two identical requests; the second optionally carrying a refresh signal. + + The first populates the L1 cache. What the second does with it is the whole + question. + """ + async def go(): + client = TestClient(TestServer(_make_app())) + await client.start_server() + try: + first = await client.get("/get_term_info", params={"id": "VFB_0001"}) + first_body = await first.json() + second = await client.get( + "/get_term_info", + params=dict({"id": "VFB_0001"}, **(params_second or {})), + headers=headers_second or {}) + second_body = await second.json() + return first_body, second_body + finally: + await client.close() + return run(go()) + + +# --------------------------------------------------------------------------- +# The cache is real, so "it re-ran" means something +# --------------------------------------------------------------------------- + +def test_a_repeat_request_is_served_from_the_l1_cache(monkeypatch): + """The control. Without it, every assertion below proves nothing. + + If a plain repeat also re-ran the worker, "the header re-ran the worker" + would be indistinguishable from "this endpoint never caches". + """ + runs = _stub_worker(monkeypatch) + first, second = _drive() + assert len(runs) == 1 + assert first["run"] == second["run"] == 1 + + +def test_the_query_parameter_still_refreshes(monkeypatch): + """``force_refresh=true`` keeps working exactly as it did. + + The header is additive; nothing about the existing spelling changes. + """ + runs = _stub_worker(monkeypatch) + _, second = _drive(params_second={"force_refresh": "true"}) + assert len(runs) == 2 + assert runs[1]["force_refresh"] is True + assert second["run"] == 2 + + +def test_the_header_alone_refreshes(monkeypatch): + """The fix. Same URL, no query parameter — so the edge key is unchanged. + + That last part is the point: this is a refresh that can heal the canonical + cache slot, which ``&force_refresh=true`` structurally cannot. + """ + runs = _stub_worker(monkeypatch) + _, second = _drive(headers_second={"X-Force-Refresh": "true"}) + assert len(runs) == 2 + assert second["run"] == 2 + + +def test_the_header_is_propagated_down_to_the_solr_cache(monkeypatch): + """Dropping the L1 entry is only half a refresh. + + If the header invalidated the in-process cache but did not reach + ``get_term_info``, the recompute would be served straight back out of the + three-month Solr entry — the same stale answer, more slowly. The flag has to + travel the whole way down. + """ + runs = _stub_worker(monkeypatch) + _, second = _drive(headers_second={"X-Force-Refresh": "true"}) + assert runs[1]["force_refresh"] is True + assert second["saw_force_refresh"] is True + + +@pytest.mark.parametrize("value", ["true", "TRUE", "1", "yes", "on", " true "]) +def test_the_accepted_spellings_match_the_edge(monkeypatch, value): + """nginx accepts ``true|1|yes|on``; accepting a narrower set would be a trap. + + An operator whose ``X-Force-Refresh: 1`` bypassed the edge but not this + service would see a fresh-looking 200 carrying stale content — the exact + failure this change removes, reintroduced by a spelling mismatch. + """ + runs = _stub_worker(monkeypatch) + _drive(headers_second={"X-Force-Refresh": value}) + assert len(runs) == 2 + + +@pytest.mark.parametrize("value", ["false", "0", "no", "off"]) +def test_an_explicit_no_is_still_a_no(monkeypatch, value): + runs = _stub_worker(monkeypatch) + _, second = _drive(headers_second={"X-Force-Refresh": value}) + assert len(runs) == 1 + assert second["run"] == 1 + + +# --------------------------------------------------------------------------- +# A misspelled header must not silently do nothing +# --------------------------------------------------------------------------- + +def test_an_unrecognised_value_is_read_as_false_and_says_so(monkeypatch): + """Silence here is the expensive failure mode. + + A bulk warm run sends this header hundreds of thousands of times. If + ``X-Force-Refresh: please`` were read as false with no comment, the whole + run would appear to succeed — 200s throughout — and refresh nothing, and + nobody would find out until the previews were still blank weeks later. + """ + _stub_worker(monkeypatch) + + async def go(): + client = TestClient(TestServer(_make_app())) + await client.start_server() + try: + response = await client.get( + "/get_term_info", params={"id": "VFB_0001"}, + headers={"X-Force-Refresh": "please"}) + return await response.json() + finally: + await client.close() + + body = run(go()) + warnings = body.get("warnings", []) + assert any("X-Force-Refresh" in w for w in warnings), warnings + # The warning has to be actionable, so it names the values that do work. + assert any("true" in w for w in warnings), warnings + + +def test_a_good_header_produces_no_warning(monkeypatch): + """Warnings that fire on correct usage get filtered out, then missed.""" + _stub_worker(monkeypatch) + + async def go(): + client = TestClient(TestServer(_make_app())) + await client.start_server() + try: + response = await client.get( + "/get_term_info", params={"id": "VFB_0001"}, + headers={"X-Force-Refresh": "true"}) + return await response.json() + finally: + await client.close() + + body = run(go()) + assert not [w for w in body.get("warnings", []) if "X-Force-Refresh" in w] + + +def test_the_header_is_not_mistaken_for_an_unknown_query_parameter(monkeypatch): + """``_unknown_param_warnings`` polices the query string, not the headers.""" + _stub_worker(monkeypatch) + + async def go(): + client = TestClient(TestServer(_make_app())) + await client.start_server() + try: + response = await client.get( + "/get_term_info", params={"id": "VFB_0001"}, + headers={"X-Force-Refresh": "true"}) + return await response.json() + finally: + await client.close() + + assert "warnings" not in run(go()) diff --git a/tests/test_param_validation.py b/tests/test_param_validation.py index a5e1411..d7f441d 100644 --- a/tests/test_param_validation.py +++ b/tests/test_param_validation.py @@ -23,7 +23,13 @@ def _make_app(monkeypatch): dispatched = [] - async def fake_dispatch(request, cache_key, worker_fn, *args, post_fn=None): + # ``known_params`` is accepted and ignored: the real ``_dispatch_to_pool`` + # grew that keyword after this stub was written, and a stub with the + # narrower signature turns every call that reaches it into a TypeError the + # handler reports as a 500 — which reads exactly like the defect these tests + # exist to catch, so the suite failed while the service was fine. + async def fake_dispatch(request, cache_key, worker_fn, *args, post_fn=None, + known_params=None): dispatched.append(cache_key) # The html handler parses this body, so it has to look like a result. return web.json_response({"html": "
tree
"}) @@ -189,5 +195,10 @@ def test_paging_hints_still_fall_back_rather_than_failing(): # asserted through the endpoint elsewhere. What is checkable here is that # the strict one is not wired into it. import inspect - src = inspect.getsource(ha_api.handle_run_query) + # Comments are stripped before the check. The question is what the handler + # *calls*, and a cross-reference in a comment — "see _query_int" — is not a + # call. Matching raw source made this fail the moment someone documented the + # very distinction the test is here to protect. + src = "\n".join(line.split("#", 1)[0] + for line in inspect.getsource(ha_api.handle_run_query).splitlines()) assert "_int_param" in src and "_query_int" not in src diff --git a/tests/test_preview_status.py b/tests/test_preview_status.py new file mode 100644 index 0000000..817b318 --- /dev/null +++ b/tests/test_preview_status.py @@ -0,0 +1,269 @@ +"""Regression tests: a cache write nobody can read makes "pending" permanent. + +Three defects sat on top of each other, and each one hid the next. + +The first is the one users saw. ``cache_result`` posted to Solr with +``commit=false`` and relied on an ``autoSoftCommit`` that the cache core does +not have (``autoSoftCommit.maxTime: -1``, ``autoCommit.openSearcher: false``). +The write was accepted, durable, and returned HTTP 200 — and never became +searchable. So every read-back missed, every ``get_term_info`` was cold, every +cold call took the two-phase fast path that blanks the previews and warms them +in the background, and the warmed answer went into the same invisible hole. +``count: -1`` — a state designed to last seconds — became the permanent answer +for every term. + +The second is what that exposed about ``-1`` itself. It has always meant "not +counted yet", which is emphatically *not* ``0`` ("no matches"); the contract is +documented in CACHING.md and honoured by the v2 frontend. But nothing in the +payload said so, so a consumer had to know. ``status`` and ``message`` make the +distinction explicit without changing what ``-1`` means. + +The third only became visible once ``status`` was load-bearing. Three validators +tested ``count >= 0`` to decide whether a result was worth caching. Read +literally that also condemns a *complete* preview whose exact total exceeded +``COUNT_CAP`` — there ``-1`` means "many", the rows are final, and there is +nothing to wait for. Any term with a large query was therefore rejected from the +cache and recomputed on every single request, forever, silently. + +The tests are grouped in that order. The first group would fail against the old +``commit=false`` write; the second and third against the old ``count >= 0`` +comparison and the missing ``status``. +""" +import json + +import pytest + +from vfbquery import solr_result_cache as src +from vfbquery import vfb_queries as vq +from vfbquery.solr_result_cache import (PREVIEW_STATUS_COMPLETE, + PREVIEW_STATUS_PENDING, + preview_is_resolved, + solr_write_params) + + +# --------------------------------------------------------------------------- +# 1. The write has to become visible +# --------------------------------------------------------------------------- + +def _clear_write_env(monkeypatch): + monkeypatch.delenv('VFBQUERY_SOLR_WRITE_COMMIT', raising=False) + monkeypatch.delenv('VFBQUERY_SOLR_COMMIT_WITHIN_MS', raising=False) + + +def test_default_write_is_non_blocking_but_visible(monkeypatch): + """The default must carry ``commitWithin`` — that is the whole fix. + + ``commit=false`` alone is what broke: it defers to a soft commit that never + happens on this core. ``commitWithin`` is honoured (the core's updateHandler + sets ``commitWithin: {softCommit: true}``), so the POST still returns + immediately while a searcher reopens inside the window. + """ + _clear_write_env(monkeypatch) + params = solr_write_params() + assert params['commit'] == 'false' + assert params['commitWithin'] == '10000' + + +def test_commit_within_window_is_configurable(monkeypatch): + _clear_write_env(monkeypatch) + monkeypatch.setenv('VFBQUERY_SOLR_COMMIT_WITHIN_MS', '2500') + assert solr_write_params()['commitWithin'] == '2500' + + +@pytest.mark.parametrize('bad', ['0', '-1', 'soon', '']) +def test_a_useless_window_falls_back_rather_than_disabling_visibility(monkeypatch, bad): + """A non-positive or unparseable window must not mean "never". + + ``commitWithin=0`` is not "commit now" — Solr reads a non-positive value as + no commitWithin at all, which is exactly the invisible write this change + exists to remove. Misconfiguration should cost a slightly different latency, + not reinstate the bug. + """ + _clear_write_env(monkeypatch) + monkeypatch.setenv('VFBQUERY_SOLR_COMMIT_WITHIN_MS', bad) + assert solr_write_params()['commitWithin'] == '10000' + + +def test_blocking_commit_is_still_available_as_an_escape_hatch(monkeypatch): + """Bulk warming wants the old behaviour; everything else should not have it. + + ``commit=true`` is a blocking hard flush, and on this deployment it can wedge + on the write.lock EIO failure mode and surface as a 503 — which is why it is + opt-in rather than the default. + """ + _clear_write_env(monkeypatch) + monkeypatch.setenv('VFBQUERY_SOLR_WRITE_COMMIT', 'true') + params = solr_write_params() + assert params == {'commit': 'true'} + assert 'commitWithin' not in params + + +class _Recorder: + """Stands in for ``requests.post`` and keeps what was sent.""" + + def __init__(self): + self.calls = [] + + def __call__(self, url, data=None, headers=None, params=None, timeout=None): + self.calls.append({'url': url, 'data': data, 'params': params}) + + class _Response: + status_code = 200 + text = '' + return _Response() + + +def _cache_for_test(monkeypatch): + _clear_write_env(monkeypatch) + monkeypatch.delenv('VFBQUERY_CACHE_READONLY', raising=False) + return src.SolrResultCache(cache_url='http://solr.invalid/cache') + + +def test_cache_result_actually_posts_commit_within(monkeypatch): + """Asserting on ``solr_write_params()`` alone would not catch the real bug. + + The defect was never in a helper — it was in the params the write path + passed. This drives ``cache_result`` and reads what went over the wire. + """ + cache = _cache_for_test(monkeypatch) + recorder = _Recorder() + monkeypatch.setattr(src.requests, 'post', recorder, raising=True) + + assert cache.cache_result('term_info', 'VFB_00000001', + {'Name': 'a term', 'count': 3}) is True + + assert len(recorder.calls) == 1 + call = recorder.calls[0] + assert call['url'] == 'http://solr.invalid/cache/update' + assert call['params']['commitWithin'] == '10000' + # And the document really is the one we asked to store. + assert json.loads(call['data'])[0]['original_term_id'] == 'VFB_00000001' + + +def test_the_expiry_delete_is_visible_too(monkeypatch): + """The same bug, on the other write path, with a nastier shape. + + An invisible delete leaves the expired document in place, so it is read back + and re-expired on every subsequent lookup: the entry can never be replaced, + only re-condemned. + """ + cache = _cache_for_test(monkeypatch) + recorder = _Recorder() + monkeypatch.setattr(src.requests, 'post', recorder, raising=True) + + cache._clear_expired_cache_document('vfb_query_term_info_VFB_00000001') + + assert len(recorder.calls) == 1 + assert recorder.calls[0]['params']['commitWithin'] == '10000' + + +# --------------------------------------------------------------------------- +# 2. "Resolved" is not the same question as "count >= 0" +# --------------------------------------------------------------------------- + +def _query(count, status=None, **extra): + preview = dict(extra) + if status is not None: + preview['status'] = status + return {'count': count, 'preview_results': preview} + + +def test_a_finished_preview_is_resolved(): + assert preview_is_resolved(_query(5, PREVIEW_STATUS_COMPLETE)) is True + + +def test_zero_matches_is_an_answer(): + """0 is a real result — "we looked, there are none" — and must be cached.""" + assert preview_is_resolved(_query(0, PREVIEW_STATUS_COMPLETE)) is True + + +def test_a_pending_preview_is_not_resolved(): + assert preview_is_resolved(_query(-1, PREVIEW_STATUS_PENDING)) is False + + +def test_a_complete_but_uncounted_preview_is_resolved(): + """The third defect, in one line. + + ``count: -1`` here means "more than COUNT_CAP", not "unknown": the rows are + final. Under the old ``count >= 0`` test this term was refused by the cache + validator on write *and* on read, so it was recomputed from scratch on every + request and could never settle. + """ + assert preview_is_resolved(_query(-1, PREVIEW_STATUS_COMPLETE)) is True + + +def test_entries_written_before_status_existed_still_read_as_complete(): + """Absence of ``status`` has to keep meaning complete. + + The cache holds three months of entries written before this key existed. If + a missing ``status`` were read as pending, shipping this would invalidate + every one of them at once and stampede the whole corpus through a cold + recompute — turning a correctness fix into an outage. + """ + assert preview_is_resolved({'count': 7, 'preview_results': {'rows': []}}) is True + assert preview_is_resolved({'count': -1, 'preview_results': {'rows': []}}) is False + + +def test_a_query_with_no_preview_block_is_not_resolved(): + assert preview_is_resolved({'count': 5}) is False + assert preview_is_resolved({'count': 5, 'preview_results': None}) is False + + +# --------------------------------------------------------------------------- +# 3. The pending state has to say what it is +# --------------------------------------------------------------------------- + +def test_blank_previews_are_labelled_pending_and_stay_uncounted(): + """The fast path still blanks previews — it just no longer lies about it. + + ``count`` must remain -1: it is the documented "not counted yet" sentinel and + the v2 frontend depends on it. What is new is that the payload now *says* + pending rather than leaving a bare -1 for the consumer to interpret. + """ + term_info = {'Queries': [ + {'query': 'ListAllAvailableImages', + 'preview_columns': ['id', 'label', 'thumbnail']}, + {'query': 'SimilarNeurons'}, + ]} + + out = vq._blank_query_previews(term_info) + + for query in out['Queries']: + preview = query['preview_results'] + assert query['count'] == vq.PREVIEW_COUNT_UNKNOWN == -1 + assert preview['status'] == PREVIEW_STATUS_PENDING + assert preview['rows'] == [] + # The message has to distinguish -1 from 0 in words, because that is + # precisely the confusion it exists to prevent. + assert 'not counted' in preview['message'] + assert 'no matches' in preview['message'] + assert preview_is_resolved(query) is False + + # Declared preview columns survive, so a client can render the empty table + # with its real headers rather than guessing. + assert out['Queries'][0]['preview_results']['headers'] == \ + ['id', 'label', 'thumbnail'] + assert out['Queries'][1]['preview_results']['headers'] == \ + ['id', 'label', 'tags', 'thumbnail'] + + +def test_the_pending_messages_all_name_the_way_out(): + """Each pending reason points at running the query directly. + + A pending preview is not an error and not a dead end: the number is unknown + because the query has not been run, and running it is the answer. A message + that only described the state would leave the caller stuck. + """ + for message in (vq.PREVIEW_PENDING_NOT_RUN, + vq.PREVIEW_PENDING_TIMEOUT, + vq.PREVIEW_PENDING_ERROR): + assert 'not counted' in message + assert 'no matches' in message + assert 'run the query' in message.lower() + + +def test_the_uncounted_complete_message_names_the_cap(): + """"Many" is only useful if the reader knows how many is many.""" + rendered = vq.PREVIEW_COMPLETE_UNCOUNTED.format(cap=vq.COUNT_CAP) + assert str(vq.COUNT_CAP) in rendered + assert 'complete' in rendered.lower()