diff --git a/hindsight-api-slim/hindsight_api/engine/memory_engine.py b/hindsight-api-slim/hindsight_api/engine/memory_engine.py index 845f255c0..56320442e 100644 --- a/hindsight-api-slim/hindsight_api/engine/memory_engine.py +++ b/hindsight-api-slim/hindsight_api/engine/memory_engine.py @@ -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() diff --git a/hindsight-api-slim/hindsight_api/engine/search/trace.py b/hindsight-api-slim/hindsight_api/engine/search/trace.py index 9beb64e39..bd0c3f5b7 100644 --- a/hindsight-api-slim/hindsight_api/engine/search/trace.py +++ b/hindsight-api-slim/hindsight_api/engine/search/trace.py @@ -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") diff --git a/hindsight-api-slim/hindsight_api/engine/search/tracer.py b/hindsight-api-slim/hindsight_api/engine/search/tracer.py index f744a71d7..35ad5819a 100644 --- a/hindsight-api-slim/hindsight_api/engine/search/tracer.py +++ b/hindsight-api-slim/hindsight_api/engine/search/tracer.py @@ -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, diff --git a/hindsight-api-slim/tests/test_search_trace.py b/hindsight-api-slim/tests/test_search_trace.py index f8e8c3e01..85911045c 100644 --- a/hindsight-api-slim/tests/test_search_trace.py +++ b/hindsight-api-slim/tests/test_search_trace.py @@ -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