feat(provider): inbound memory-call observe log (#17 observe brick)

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.

persistent-memory.md

@@ -56,13 +56,21 @@ background shell (`ratatoskr-provider`, `0.0.0.0:8390`, env-sourced from
 Worldtree **v0.35.2** (`10.250.50.152`): handshake 200 + `affect.emit` 200 →
 durable row persisted, opacity held.
 
-**MEMORY plane: contract done, TDD next.**
-`docs/contracts/bifrost_memory_provider.contract.md` v1.1 (Heid-panel-reviewed,
-committed `1f94e5f`). NEXT (fresh session): add `sqlite-vec` to the `provider`
-extra → TDD (tracer `basic_upsert` → search/scope-isolation/optimistic-lock/
-conflict → #195 parity vs `InMemoryMemoryStore`) → `/heid-code-review` → ship a
-`ratatoskr-memory-provider` dev shell. Worldtree v0.35.3 already negotiates the
-basic memory plane — the memory server is the only missing piece.
+**MEMORY plane: PROVIDER LIVE-PROVEN** (v0.17.3, commit `cd12951`; provider
+running on `0.0.0.0:8391` as a dev bg shell). Store + dev shell shipped (7
+contract blocks, 26+4 tests, #195 parity, heid-reviewed zero-drift) AND the
+live round-trip ran against personal **v0.35.3**: handshake + `upsert_many`
+(persist) + `search` (recall-dispatch) all green; `memory.db` holds 3 durable
+chunks (2 facts + 1 promoted question, scope `end_user:smoke-user`, 1024-d
+vec-indexed). **Proven: persist + dispatch + our search-correctness** — direct
+probe (embed the recall query via gateway `qwen3-embedding`, search our live
+store) recalls the right fact at cosine 0.60, correctly ranked. **NOT proven,
+and upstream (not ours): end-to-end recall-INJECTION** — Worldtree's
+recall-assembly doesn't surface our hits into the prompt (cold-session probe:
+search dispatched 200 but the model said "no memory"). worldtree-dev looped in
+(thread `01KV7JH8…`; #295 held open). Provider stays up with the live fixture.
+So NO minor bump / "all-green" announce until worldtree-dev closes the injection
++ question-promotion gaps.
 
 **Sindra:** a REGISTERED Tier-3 agent (`ratatoskr:sindra`, was model
 `artemis-31b-v1i`) — registration is REQUIRED to use a Tier-3 character (a
@@ -78,9 +86,10 @@ registration.
 `~/.config/ratatoskr/provider.env` (mode 600, nh3-dev) — `consumer="ratatoskr"`,
 HS256 = the API-key STRING utf-8-encoded; rotate via infra-ops.
 
-**Unpushed:** `main` is 3 commits ahead of origin (origin at `d90a58d`/v0.17.1;
-local at `1f94e5f`) — `bcdcd71` (v0.17.2), `eebab46`, `1f94e5f` + the local
-`v0.17.2` tag are unpushed. Push is the operator's call.
+**Pushed:** `main` is in sync with `origin` (pushed through `e57b054`); tags
+`v0.17.3` + a straggler `v0.8.2` pushed. Only `graphify-out/GRAPH_REPORT.md`
+runs dirty (auto-regenerated by the commit hook — generated artifact, not
+chased).
 
 **Still standing from before:** Worldtree spec pin v0.29.0 (`562001a`) for the
 conversation-API/TUI surface (untouched by the Bifrost work). Codex-first pilot
@@ -170,3 +179,10 @@ defense against re-attempting the same cul-de-sac.
 - `[2026-06-15]` **"Sindra hasn't been registered" was an under-verified inference — WRONG.** Concluded it from grepping ratatoskr's CODE (`sindra` absent from `src/`), but Tier-3 registration is SERVER-SIDE (`POST /agents/define` on the Worldtree instance) — a code grep structurally can't see it. Registration IS required to use a Tier-3 character (a session against an unregistered `agent_id` 404s), so since Sindra has been used, she WAS registered (`ratatoskr:sindra`). **Rule: to check whether a Tier-3 agent exists, query the Worldtree instance's `GET /agents`, never the consumer repo's code.** (Residual: the v0.35.2 personal rebuild may have wiped her — re-verify.)
 - `[2026-06-14]` **Artifact-only contract review can't validate against a dependency's ACTUAL behavior.** `/heid-contract-review` sees only the contract, never the external library (bifrost) — so "the consumer under-built against bifrost's real semantics" is invisible to it by construction (the affect idempotency model shipped wrong because of this). Real-lib TDD against the shipped library + the executable reference store + the #195 parity test are the gate for any consumer plane with non-trivial state semantics. Don't treat a clean contract review as evidence the code matches the dependency.
 - `[2026-06-15]` **"byte-equal" round-trip slip propagated affect→memory via copy-paste.** The affect contract's byte-identical→semantic fix reappeared in the memory contract's INV-001 (sibling copy). Only an INDEPENDENT `/heid-contract-review` of the memory contract re-caught it. **Paraphrase every sibling contract fresh — don't amortize one review across a family; copies carry the parent's slips.** (also a feedback auto-memory)
+- `[2026-06-15]` **Canonical sync retired the issue-scoped parser staleness** (predicted by the 2026-05-21 entry's "until canonical bumps"). `contract_parser.py` synced to v2.1 (`f1fdfdb6→e10a4460`, commit `d85ab43`): now validates issue-scoped frontmatter (`target_module`/`scope`/`prd`) + four v2.1 test categories (scenario/trace/adversarial/property). Issues #3/#4 went FAIL→WARN (0 errors). The old "treat parser ERROR-on-issue-scoped as expected" note no longer applies.
+- `[2026-06-15]` **Refreshed #3/#4 presenter contracts to the shipped TUI model** (commit `335c835`). Both still described the abandoned single-`RichLog` double-display model; rewrote to the 4-pane live-Markdown reality (v0.5.0–v0.14.0 + Worldtree #201/#204) across INV-005, the `[performance]` constraint, the COMPOSE sketch, the `CLASS TuiPresenterState` block, both `render`/`_stream_turn_worker` blocks, and the `_cancel_via_sse` call site — plus the STEPS the v2.1 parser flagged missing. Code unchanged; contract-truth catching up to shipped code. Scope ballooned one-block→contract-wide mid-task; surfaced to operator before rewriting the INV-005 trade-off invariant.
+- `[2026-06-15]` **Memory plane TDD'd + shipped** (commit `cd12951`, v0.17.3). Impl decisions worth keeping: vec0 `distance_metric=cosine` set at table creation (`score = 1 − distance`); `search` over-fetches ALL candidates by cosine then scope-filters in Python so `top_k` counts IN-SCOPE hits (INV-005, contract STEP 2 `indicative`); idempotency_id = reference 4-tuple `("default",verb,_ctx_actor(ctx),key)` pipe-joined as the SQLite PK, digest = sha256 canonical-JSON; `_ctx_actor` = `job_id|jwt_sub|session_id` (memory reference's 3-level, vs affect's 2-level). **heid-code-review panel returned zero true drift**; adopted 5 cheap contract-anchored fixups (scope_filter dict guard, `top_k≤0→[]`, stronger scope-isolation / delete-hit-search / handshake-POST tests), accepted 6 with reasoning. **Partial-map optimistic-lock semantics pinned to the reference via an `expected_revisions` parity test** — resolved a Hulda finding deterministically (the affect-plane lesson: TDD against the shipped lib is the gate, not judgment).
+- `[2026-06-15]` **Memory provider LIVE-PROVEN against personal v0.35.3 (persist + dispatch + search-correctness); recall-injection is upstream.** worldtree-dev's Tier-3 promotion recipe (via infra-ops): memory-call fires from Tier-3 PROMOTION, gated at `service.py:2623` on `ctx.kind=="consumer_defined"` AND `ctx.memory_config is not None` (the agent must be DEFINED WITH a `memory` block — `ValidatedMemoryConfig {tier3_dreaming:false}`, dim 1024) AND handshake-granted memory caps AND `embedding_dim==1024`. `memory.agent_self_enabled` is NOT the gate (only the #248 self-candidate branch). Binding = `POST /sessions BifrostBindingRequest{endpoint_url}`, handshake `caps=["affect","memory"]`, **`binding.scope` null** (per-op scopes auto-minted: upsert_many→`memory:write`, search→`memory:read`). A `BIFROST_CLIENT_ALLOWED_HOSTS` allowlist gates the endpoint (Worldtree-side config — infra-ops added `:8391`). HTTP + HS256 both work in dev. (smoke wiring thread `01KV7D82MJYB…`)
+- `[2026-06-15]` **Diagnostic: our recall-search is SOUND — the cross-session recall gap is UPSTREAM, not the store — and it caught an upstream bug.** Embedded the recall query via gateway `qwen3-embedding` + searched our live store directly → the dark-chocolate fact recalls at cosine 0.60, correctly ranked above the unrelated name fact (0.16). So the cold-session recall failure is Worldtree's recall-assembly/injection (hits not reaching the prompt), NOT our search. ALSO found a latent UPSTREAM bug: a recall QUESTION got promoted as a durable chunk and ranks **#1 (0.70 > the fact's 0.60)**, polluting recall. Relayed to worldtree-dev (thread `01KV7JH8…`). **This is exactly #17's thesis — ratatoskr-as-provider caught an upstream bug invisible from the chat side.**
+- `[2026-06-15]` **"Wire 200 ≠ recall works" — prove recall efficacy at the model's answer in a COLD (history-free) session, not on the wire.** A `search`/memory-call returns 200 whether or not its results are injected into the prompt, and same-session "recall" can be plain session history. infra-ops' cold cross-session probe caught my premature "all-green" (search dispatched 200, model had no memory). Don't call cross-session recall proven from a clean wire.
+- `[2026-06-15]` **Issue #17 filed — Bifrost-binding for the chat client (self-drive + correlated-log affect/memory ops).** REVERSES design-brief §6's "no Bifrost-binding consumer support" — that negative clause predates ratatoskr's provider identity (2026-06-14), so the canary now owns both ends but its client can't drive its own provider (`create_session` sends only `{agent_id, end_user_id}`; no Bifrost `endpoint_url`). Today's smoke proved the substrate (bind→dispatch→persist); only the observe/log channel design (open question #5) remains. The recall-injection caveat is upstream and doesn't block #17. NEXT on #17: `/heid` consult on the now-grounded framing → contract → TDD. (tracked: Gitea #17, labels enhancement/observability/tui)

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"

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:

uv.lock

@@ -1052,7 +1052,7 @@ wheels = [
 
 [[package]]
 name = "ratatoskr"
-version = "0.17.3"
+version = "0.17.4"
 source = { editable = "." }
 dependencies = [
     { name = "httpx" },