From 2fef6e39f950d70050896507218ce1522d1ac1a5 Mon Sep 17 00:00:00 2001
From: Vuong Hoang <vh@phasefinal.com>
Date: Tue, 16 Jun 2026 01:15:16 -0700
Subject: [PATCH] feat(provider): inbound memory-call observe log (#17 observe
 brick)
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

Structured [memory-provider] request/response logging on the memory-call
path: search REQUEST (scope_filter, top_k) + RESPONSE (chunk_ids, scores,
scope), plus concise entry lines on upsert_many/delete_many. Self-contained
stdout handler so the lines reach the provider stdout under uvicorn.

Additive observability only — no search-semantics change (AND-parity with
bifrost's reference store holds). This is the first concrete brick of #17's
observe half, and the lens that root-caused #295's cold-recall miss (the
persist/recall scope-axis asymmetry) from the provider side.
---
 pyproject.toml                         |  2 +-
 src/ratatoskr/provider/memory_store.py | 45 ++++++++++++++++++++++++--
 uv.lock                                |  2 +-
 3 files changed, 44 insertions(+), 5 deletions(-)

diff --git a/pyproject.toml b/pyproject.toml
index c8f93ad..927d374 100644
--- a/pyproject.toml
+++ b/pyproject.toml
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
 
 [project]
 name = "ratatoskr"
-version = "0.17.3"
+version = "0.17.4"
 description = "Worldtree Conversation API debug TUI — multi-pane observability dashboard"
 readme = "README.md"
 requires-python = ">=3.12"
diff --git a/src/ratatoskr/provider/memory_store.py b/src/ratatoskr/provider/memory_store.py
index bc75ad7..19a722a 100644
--- a/src/ratatoskr/provider/memory_store.py
+++ b/src/ratatoskr/provider/memory_store.py
@@ -14,7 +14,9 @@ from __future__ import annotations
 
 import hashlib
 import json
+import logging
 import sqlite3
+import sys
 import time
 from typing import Any
 
@@ -31,6 +33,17 @@ from bifrost.reference_server import JwtVerifier
 _SHORT_RETRY_TTL_SECONDS = 300
 _DURABLE_JOB_TTL_SECONDS = 24 * 60 * 60
 
+# Inbound memory-call observability (#17 observe brick). A self-contained
+# stdout handler so the lines reliably reach the provider's stdout regardless
+# of uvicorn's logging config. INFO-level, no propagation to root.
+_log = logging.getLogger("ratatoskr.provider.memory")
+if not _log.handlers:
+    _h = logging.StreamHandler(sys.stdout)
+    _h.setFormatter(logging.Formatter("%(asctime)s [memory-provider] %(message)s"))
+    _log.addHandler(_h)
+    _log.setLevel(logging.INFO)
+    _log.propagate = False
+
 
 def _ctx_actor(ctx: Any) -> str:
     """Reference `_ctx_actor`: actor = job_id | jwt_sub | session_id (never the record)."""
@@ -113,6 +126,11 @@ class RatatoskrMemoryStore:
     ) -> dict:
         if not (isinstance(idempotency_key, str) and idempotency_key):  # PRE-001
             raise InvalidArguments("idempotency_key required")
+        _log.info(
+            "memory-call upsert_many REQUEST: %d record(s) idempotency_key=%s actor=%s scopes=%s",
+            len(records), idempotency_key, _ctx_actor(ctx),
+            [r.get("scope") for r in records],
+        )
         # INV-002: idempotency_id = ("default", verb, actor-from-ctx, key); digest over payload.
         digest = _payload_digest({"records": records, "expected_revisions": expected_revisions})
         idempotency_id = "|".join(("default", "upsert_many", _ctx_actor(ctx), idempotency_key))
@@ -187,11 +205,31 @@ class RatatoskrMemoryStore:
             raise InvalidArguments("metadata_filter is unsupported in v1")
         if scope_filter is not None and not isinstance(scope_filter, dict):  # STEP 1
             raise InvalidArguments("scope_filter must be a flat {axis: value} dict")
+        _log.info(
+            "memory-call search REQUEST: scope_filter=%r top_k=%s metadata_filter=%r vec_dim=%d",
+            scope_filter, top_k, metadata_filter, len(vector),
+        )
+
+        def _emit(rs: list[dict]) -> list[dict]:
+            _log.info(
+                "memory-call search RESPONSE: %d hit(s) %s",
+                len(rs),
+                [
+                    {
+                        "chunk_id": r["chunk_id"],
+                        "score": round(r["score"], 4),
+                        "scope": r["chunk"].get("scope"),
+                    }
+                    for r in rs
+                ],
+            )
+            return rs
+
         if top_k <= 0:  # POST-001: at most top_k
-            return []
+            return _emit([])
         total = self._conn.execute("SELECT COUNT(*) FROM memory_vec").fetchone()[0]
         if total == 0:
-            return []
+            return _emit([])
         # Over-fetch every candidate ranked by cosine distance, then scope-filter and
         # take top_k — so top_k counts IN-SCOPE hits (INV-005), not pre-filter hits.
         rows = self._conn.execute(
@@ -216,7 +254,7 @@ class RatatoskrMemoryStore:
             )
             if len(results) >= top_k:
                 break
-        return results
+        return _emit(results)
 
     async def get(self, chunk_id: str) -> dict | None:
         # INV-001: verbatim round-trip + an attached revision key, or None.
@@ -241,6 +279,7 @@ class RatatoskrMemoryStore:
 
     async def delete_many(self, ids: list[str]) -> dict:
         # One transaction: chunk row + its vec row leave together (no orphan vec rows).
+        _log.info("memory-call delete_many REQUEST: ids=%s", ids)
         deleted = 0
         with self._conn:
             for chunk_id in ids:
diff --git a/uv.lock b/uv.lock
index 804386d..cf36e1a 100644
--- a/uv.lock
+++ b/uv.lock
@@ -1052,7 +1052,7 @@ wheels = [
 
 [[package]]
 name = "ratatoskr"
-version = "0.17.3"
+version = "0.17.4"
 source = { editable = "." }
 dependencies = [
     { name = "httpx" },