fix(recall): report the caller's query_timestamp in the search trace (#4227)

`trace.query.timestamp` was `datetime.now(UTC)` at finalize time, so a recall
anchored with `query_timestamp` reported today's date even though the anchor
had been applied to recency scoring. Anyone debugging a ranking read the field
and concluded their anchor was ignored.

The tracer now takes the resolved anchor (`_recall_scoring_now(question_date)`,
the same value the scoring uses) and records it, falling back to now when the
caller supplied none.

Fixes #4217
This commit is contained in:
Nicolò Boschi
2026-09-08 17:25:46 +02:00
committed by GitHub
parent da0444a72a
commit e366ff407e
4 changed files with 46 additions and 4 deletions
@@ -7468,7 +7468,17 @@ class MemoryEngine(MemoryEngineInterface):
# handful of floats and they are what makes a recall log account for its own duration --
# the numbered stages stop at token filtering, so hydration, assembly and entity building
# were measured and then thrown away unless someone happened to pass `trace=true`.
tracer = SearchTracer(query, thinking_budget, max_tokens, tags=tags, tags_match=tags_match)
# The trace's timestamp is the anchor the ranking was computed against -- the caller's
# `question_date` when they supplied one -- not the moment the trace happened to be built.
# Reporting wall-clock here made an applied anchor look ignored (#4217).
tracer = SearchTracer(
query,
thinking_budget,
max_tokens,
tags=tags,
tags_match=tags_match,
query_timestamp=_recall_scoring_now(question_date),
)
tracer.phases_only = not enable_trace
tracer.start()
@@ -23,7 +23,9 @@ class QueryInfo(BaseModel):
query_text: str = Field(description="Original query text")
query_embedding: list[float] = Field(description="Generated query embedding vector")
timestamp: datetime = Field(description="When the query was executed")
timestamp: datetime = Field(
description="As-of anchor the query was resolved against: the caller's query_timestamp when supplied, otherwise the execution time"
)
budget: int = Field(description="Maximum nodes to explore")
max_tokens: int = Field(description="Maximum tokens to return in results")
tags: list[str] | None = Field(default=None, description="Tags filter applied to recall")
@@ -53,6 +53,7 @@ class SearchTracer:
max_tokens: int,
tags: list[str] | None = None,
tags_match: str | None = None,
query_timestamp: datetime | None = None,
):
# `phases_only` keeps the timings and drops everything expensive. Phase metrics are a
# handful of floats; the rest of a trace is every candidate's text, the query embedding and
@@ -69,12 +70,15 @@ class SearchTracer:
max_tokens: Maximum tokens to return in results
tags: Tags filter applied to recall
tags_match: Tags matching mode (any, all, any_strict, all_strict)
query_timestamp: The as-of anchor the query was resolved against, when the
caller supplied one. Defaults to the moment the trace is finalized.
"""
self.query_text = query
self.budget = budget
self.max_tokens = max_tokens
self.tags = tags
self.tags_match = tags_match
self.query_timestamp = query_timestamp
# Trace data
self.query_embedding: list[float] | None = None
@@ -393,7 +397,7 @@ class SearchTracer:
query_info = QueryInfo(
query_text=self.query_text,
query_embedding=self.query_embedding or [],
timestamp=datetime.now(UTC),
timestamp=self.query_timestamp or datetime.now(UTC),
budget=self.budget,
max_tokens=self.max_tokens,
tags=self.tags,
+27 -1
View File
@@ -34,6 +34,28 @@ def test_rrf_trace_preserves_flattened_source_ranks():
assert tracer.rrf_merged[0].source_ranks == {"semantic_rank": 1, "bm25_rank": 2}
def test_trace_timestamp_records_the_query_anchor():
"""The trace reports the as-of anchor the ranking used, not when it was built (#4217)."""
anchor = datetime(2020, 1, 1, tzinfo=timezone.utc)
tracer = SearchTracer(query="test", budget=10, max_tokens=100, query_timestamp=anchor)
tracer.start()
trace = tracer.finalize([])
assert trace.query.timestamp == anchor
def test_trace_timestamp_falls_back_to_now_without_an_anchor():
"""With no caller anchor the trace still reports a usable execution time."""
before = datetime.now(timezone.utc)
tracer = SearchTracer(query="test", budget=10, max_tokens=100)
tracer.start()
trace = tracer.finalize([])
assert before <= trace.query.timestamp <= datetime.now(timezone.utc)
@pytest.mark.asyncio
async def test_search_with_trace(memory, request_context):
"""Test that search with enable_trace=True returns a valid SearchTrace."""
@@ -61,7 +83,8 @@ async def test_search_with_trace(memory, request_context):
request_context=request_context,
)
# Search with tracing enabled
# Search with tracing enabled, anchored to an explicit as-of date
question_date = datetime(2020, 1, 1, tzinfo=timezone.utc)
search_result = await memory.recall_async(
bank_id=bank_id,
query="Who works at Google?",
@@ -69,6 +92,7 @@ async def test_search_with_trace(memory, request_context):
budget=Budget.LOW, # 20,
max_tokens=512,
enable_trace=True,
question_date=question_date,
request_context=request_context,
)
@@ -84,6 +108,8 @@ async def test_search_with_trace(memory, request_context):
assert trace["query"]["query_text"] == "Who works at Google?"
assert trace["query"]["budget"] == 100 # Budget.LOW = 100
assert trace["query"]["max_tokens"] == 512
# The anchor the caller asked for, not the moment the trace was built (#4217)
assert trace["query"]["timestamp"] == question_date
assert len(trace["query"]["query_embedding"]) > 0, "Query embedding should be populated"
# Verify entry points