feat(logs): logs données restructurés — identité en préfixe, trace résolution/barrière, inspection outbox

Chemin données bas-niveau du polyfill rendu lisible pour diagnostiquer en session live :

- Format identité-en-premier : `[<identity>][polyfill] OP shortNuri (label)` ;
  console.error épars (store-registry, inbox) unifiés au même préfixe.
- Trace (derrière le flag debug) : issue de la barrière ensureRepoOpen
  (synced|timed-out + durée) et résultat sémantique de chaque étage de résolution
  (resolvePointer/canonicalDoc/resolveAccount/resolveShimDoc/readScopeIndex).
- outbox-log.ts (nouveau) : inspection read-only de l'outbox hors-ligne au
  démarrage de session ; console.warn si non vide (anomalie, toujours visible),
  sous flag si vide. Le comptage seul est fiable (payloads BARE opaques côté JS).

Pas de changement fonctionnel. bun test 126 pass ; tsc 0 erreur.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014GbGgNEHRejVKoREvFuDFg

packages/client/src/access-log.ts

@@ -56,11 +56,39 @@ export function enabled(): boolean {
  * (`getCurrentUser`) — the account/space the operation is scoped under, which is
  * the discriminating signal for the isolation leak. NOT the physical wallet id
  * (shared, constant → useless). `(none)` when no identity is set yet (startup).
+ * Exported so every other polyfill-layer log site (store-registry, inbox,
+ * outbox-log, …) shares the exact same identity resolution as the access log,
+ * instead of re-deriving it — see {@link accessLogPrefix}.
  */
-function activeIdentity(): string {
+export function activeIdentity(): string {
   return getCurrentUser() ?? "(none)";
 }
 
+/**
+ * The common line prefix for every polyfill-layer low-level-data-path log:
+ * `[<identity>][polyfill]` — identity FIRST (the discriminating scan signal),
+ * `[polyfill]` glued right after with no space between the two brackets. Used by
+ * {@link logAccess} itself, by the unified `console.error`s in store-registry.ts /
+ * inbox.ts, and by the BARRIER / stage-resolution / OUTBOX lines (open-repo.ts,
+ * store-registry.ts, outbox-log.ts) — one single prefix builder so every polyfill
+ * log line is visually groupable by identity when scanning a live session.
+ */
+export function accessLogPrefix(): string {
+  return "[" + activeIdentity() + "][polyfill]";
+}
+
+/**
+ * Emit one CONCISE diagnostic line — ONLY when {@link enabled} — prefixed by
+ * {@link accessLogPrefix}. Used for the precise data-path trace (BARRIER
+ * resolution, per-stage resolution outcome, the empty-OUTBOX line): a single
+ * line per stage/event, never a dump. Callers pass the fully-composed suffix
+ * (e.g. `"BARRIER " + shortNuri(nuri) + " synced (842ms)"`).
+ */
+export function logStage(line: string): void {
+  if (!enabled()) return;
+  console.log(accessLogPrefix() + " " + line);
+}
+
 /**
  * Shorten a NURI for the access log: the full form (`did:ng:o:<RepoID>:v:<...>`,
  * ~100 chars) is too verbose to scan. Drop the `did:ng:o:` prefix and the `:v:<...>`
@@ -77,11 +105,13 @@ export function shortNuri(nuri: string): string {
 /**
  * Log one document access — but ONLY when {@link enabled}. Off → returns
  * immediately, prints nothing. Format:
- *   `[polyfill] [<identity>] READ <shortNuri> (<label>)` — optionally with `<extra>`
- * appended (e.g. ` → 3 rows`, a strong signal a doc rendered data under an identity
- * that should see nothing). The `[polyfill]` prefix marks these as SDK-layer access
- * logs (distinct from the consumer app's own logs). The NURI is shortened by
- * {@link shortNuri} to keep the line scannable.
+ *   `[<identity>][polyfill] READ <shortNuri> (<label>)` — identity FIRST (the
+ * discriminating scan signal), `[polyfill]` glued right after with no space
+ * between the two brackets — optionally with `<extra>` appended (e.g. ` → 3
+ * rows`, a strong signal a doc rendered data under an identity that should see
+ * nothing). The `[polyfill]` tag marks these as SDK-layer access logs (distinct
+ * from the consumer app's own logs). The NURI is shortened by {@link shortNuri}
+ * to keep the line scannable.
  */
 export function logAccess(
   op: AccessOp,
@@ -91,6 +121,6 @@ export function logAccess(
 ): void {
   if (!enabled()) return;
   console.log(
-    "[polyfill] [" + activeIdentity() + "] " + op + " " + shortNuri(nuri) + " (" + label + ")" + (extra ?? ""),
+    accessLogPrefix() + " " + op + " " + shortNuri(nuri) + " (" + label + ")" + (extra ?? ""),
   );
 }

packages/client/src/inbox.ts

@@ -29,6 +29,7 @@ import { subscribeDoc } from "./subscribe";
 import { ensureRepoOpen } from "./open-repo";
 import { getCurrentUser, getStoreRegistryDeps } from "./polyfill";
 import { escapeLiteral } from "./sparql";
+import { accessLogPrefix } from "./access-log";
 import type { Nuri, PrincipalId } from "./types";
 
 // --- deposit model --------------------------------------------------------
@@ -255,7 +256,7 @@ export function watch(
         onDeposits(deposits);
       }
     } catch (error) {
-      console.error("[inbox] watch read failed:", error);
+      console.error(accessLogPrefix() + " watch read failed:", error);
     }
   };
 

packages/client/src/open-repo.ts

@@ -61,6 +61,7 @@
 
 import { getConfig, getStoreRegistryDeps } from "./polyfill";
 import { subscribeDoc, type Unsubscribe } from "./subscribe";
+import { logStage, shortNuri } from "./access-log";
 import type { Nuri } from "./types";
 
 /**
@@ -182,6 +183,11 @@ export async function ensureRepoOpen(nuri: Nuri): Promise<void> {
 
   // Subscribed, first `State` not yet seen.
   syncState.set(nuri, "syncing");
+  // Barrier clock: how long the subscribe→first-State (or fallback) round-trip
+  // took, surfaced on the BARRIER trace line below — the most important line in
+  // the whole low-level data-path trace: it distinguishes a genuine absence
+  // (`synced` → a 0-row read means it) from a not-yet-synced read (`timed-out`).
+  const barrierStartedAt = Date.now();
 
   const p = (async () => {
     await new Promise<void>((resolve) => {
@@ -191,6 +197,7 @@ export async function ensureRepoOpen(nuri: Nuri): Promise<void> {
         if (settled) return;
         settled = true;
         syncState.set(nuri, "synced");
+        logStage("BARRIER " + shortNuri(nuri) + " synced (" + (Date.now() - barrierStartedAt) + "ms)");
         resolve();
       };
       // Bounded fallback: proceed WITHOUT a `State`, but mark "timed-out" — NOT
@@ -200,6 +207,7 @@ export async function ensureRepoOpen(nuri: Nuri): Promise<void> {
         if (settled) return;
         settled = true;
         syncState.set(nuri, "timed-out");
+        logStage("BARRIER " + shortNuri(nuri) + " timed-out (" + (Date.now() - barrierStartedAt) + "ms)");
         resolve();
       };
       // The bootstrap subscription is kept ALIVE for the session — holding it open

packages/client/src/outbox-log.ts

@@ -0,0 +1,98 @@
+/**
+ * outbox-log — read-only diagnostic inspection of `@ng-org/web`'s offline write
+ * outbox, at session bootstrap (polyfill-era, low-level-data-path trace).
+ *
+ * ── What this surfaces ──────────────────────────────────────────────────────
+ * `@ng-org/web` (the real injected SDK) queues writes made while offline/
+ * disconnected in an "outbox", persisted client-side in `sessionStorage` by the
+ * WASM verifier (see `sdk/rust/src/local_broker.rs` `JsStorageConfig::
+ * get_js_storage_config` in the `nextgraph-rs` core repo — read-only reference,
+ * NOT vendored here). A non-empty outbox at session start is an ANOMALY worth
+ * surfacing unconditionally: it means writes from a previous (disconnected)
+ * session are still queued and haven't reached the broker yet.
+ *
+ * ── sessionStorage key shapes (verified in the core repo, not guessed) ──────
+ * The outbox is keyed per LOCAL PEER id (`peer_id`, the persistent local peer's
+ * pubkey — NOT the ng-eventually shim's `account`/`identity` concept), via two
+ * key families written by `session_write`/read by `session_read`:
+ *   - `ng_peer_last_seq@<peerId>`         — the peer's last reserved seq number.
+ *   - `ng_outboxes@<peerId>@start`        — the seq number the outbox starts at.
+ *   - `ng_outboxes@<peerId>@<00000-idx>`  — one queued (base64url + BARE-encoded)
+ *     event per zero-padded index, contiguous from 0 until the first miss (the
+ *     exact shape `outbox_read_function` walks — see `local_broker.rs`).
+ * We don't know `peerId` ahead of time (it's internal to the injected SDK), so
+ * we DISCOVER it by scanning `sessionStorage` for `@start` markers instead of
+ * requiring it to be passed in — this also means the probe works unchanged
+ * however many peers/wallets the browser session has touched.
+ *
+ * ── Read-only, defensive, best-effort ────────────────────────────────────────
+ * This NEVER writes or deletes a key (unlike the real `outbox_read_function`,
+ * which drains on read) — it only counts. The queued event bytes are opaque
+ * (BARE-encoded Rust structs, base64url'd); decoding them to report concrete
+ * write TARGETS (topics/docs) would mean duplicating the WASM verifier's wire
+ * format in this polyfill, which is explicitly out of scope (SDK internals live
+ * in the `@ng-eventually/client`-independent core repo, per this repo's
+ * doctrine) — so only the pending COUNT is reported, never fabricated targets.
+ * `sessionStorage` access itself can throw (sandboxed iframe, disabled storage —
+ * see the exact error string handled in the core repo's `main.ts`
+ * `convert_error`), so the whole probe is wrapped in one try/catch: unavailable
+ * → skip silently, never throw into the caller.
+ *
+ * Polyfill-era; removed at the real multi-store migration alongside the rest of
+ * this low-level trace instrumentation.
+ */
+
+import { accessLogPrefix, logStage } from "./access-log";
+
+/** Matches an outbox "start" marker key, capturing the peer id. */
+const OUTBOX_START_KEY = /^ng_outboxes@(.+)@start$/;
+
+/** Safety bound on the per-peer index walk, so a corrupted/mocked storage
+ *  (e.g. a `@start` marker with no matching index gaps) can't spin forever.
+ *  Real outboxes are queued-while-offline writes — nowhere near this size. */
+const MAX_SCAN_PER_PEER = 10_000;
+
+/**
+ * Inspect the outbox NOW and log its state — count only, never targets (see
+ * module doc). Non-empty → `console.warn`, ALWAYS printed (anomaly, not gated
+ * by the access-log flag). Empty → a normal {@link logStage} line, gated by the
+ * access-log flag like the rest of the low-level trace. Read-only: never
+ * mutates `sessionStorage`. Never throws.
+ */
+export function inspectOutbox(): void {
+  try {
+    const storage = (globalThis as any)?.sessionStorage;
+    if (!storage) return;
+
+    const peers = new Set<string>();
+    const length: number = storage.length ?? 0;
+    for (let i = 0; i < length; i++) {
+      const key = storage.key?.(i);
+      if (!key) continue;
+      const m = OUTBOX_START_KEY.exec(key);
+      const peerId = m?.[1];
+      if (peerId) peers.add(peerId);
+    }
+
+    let total = 0;
+    for (const peer of peers) {
+      let idx = 0;
+      while (idx < MAX_SCAN_PER_PEER) {
+        const idxKey = "ng_outboxes@" + peer + "@" + String(idx).padStart(5, "0");
+        if (storage.getItem(idxKey) === null) break;
+        total++;
+        idx++;
+      }
+    }
+
+    if (total > 0) {
+      // Anomaly: ALWAYS visible, regardless of the access-log flag.
+      console.warn(accessLogPrefix() + " OUTBOX " + total + " pending write(s)");
+    } else {
+      logStage("OUTBOX empty");
+    }
+  } catch {
+    // sessionStorage unavailable / access denied — skip silently. Diagnostic
+    // only, never a hard dependency of the read/write path.
+  }
+}

packages/client/src/polyfill.ts

@@ -12,6 +12,7 @@ import type { NgLike, UseShapeLike, PrincipalId } from "./types";
 import type { RegistrySession } from "./store-registry";
 import { CapRegistry } from "./caps";
 import { setAccessLog } from "./access-log";
+import { inspectOutbox } from "./outbox-log";
 
 /**
  * Consumer-injected dependencies of the storeRegistry (polyfill-era). The
@@ -99,8 +100,26 @@ export function resetConfig(): void {
  * disappears at migration.
  */
 export function configureStoreRegistry(deps: StoreRegistryDeps): void {
+  // Fire the outbox inspection (Volet 3 of the low-level data-path trace) once,
+  // on the FIRST successful `getSession()` resolution — the most reliable
+  // "a session is established" signal available: every low-level reader/writer
+  // (store-registry, open-repo, read-model, subscribe, inbox) reaches its
+  // session through this SAME injected `getSession`, so wrapping it HERE catches
+  // the first success from whichever caller happens to run first, instead of
+  // tying the probe to one particular call site. Only on SUCCESS (an error
+  // propagates untouched, exactly as before) and only ONCE per
+  // `configureStoreRegistry()` call (a fresh session config → a fresh check).
+  let outboxInspected = false;
+  const getSession = async (): Promise<RegistrySession> => {
+    const session = await deps.getSession();
+    if (!outboxInspected) {
+      outboxInspected = true;
+      inspectOutbox();
+    }
+    return session;
+  };
   registryDeps = {
-    getSession: deps.getSession,
+    getSession,
     normalizeId: deps.normalizeId ?? ((id: string) => id.trim()),
     // Default: single read (no re-read). Only the real-broker consumers (app + e2e)
     // opt into the bounded pointer micro-guard; unit fakes stay synchronous.

packages/client/src/store-registry.ts

@@ -63,6 +63,7 @@ import { docCreate, sparqlUpdate, sparqlQuery } from "./docs";
 import { getStoreRegistryDeps } from "./polyfill";
 import { ensureRepoOpen } from "./open-repo";
 import { escapeLiteral, escapeIri, assertNuri } from "./sparql";
+import { accessLogPrefix, logStage, shortNuri } from "./access-log";
 import type { Nuri, Scope } from "./types";
 
 // --- sharedWalletShim model ----------------------------------------------
@@ -248,11 +249,20 @@ function bindingValue(row: Record<string, { value: string }>, key: string): stri
  */
 function canonicalDoc(rows: Array<Record<string, { value: string }>>, key: string): Nuri {
   let chosen = "";
+  const distinct = new Set<string>();
   for (const row of rows) {
     const v = bindingValue(row, key);
     if (!v) continue;
+    distinct.add(v);
     if (chosen === "" || v < chosen) chosen = v;
   }
+  // Stage trace: which doc got picked, and out of how many DISTINCT candidate
+  // values — >1 flags residual fork residue (see the module doc above) even
+  // when resolution still converges correctly on the canonical (smallest) one.
+  logStage(
+    "canonicalDoc(" + key + ") → " + (chosen ? shortNuri(chosen) : "none") +
+      " (" + distinct.size + (distinct.size === 1 ? " candidate)" : " candidates)"),
+  );
   return chosen;
 }
 
@@ -327,15 +337,19 @@ async function resolvePointer(): Promise<Nuri> {
     try {
       const result = await sparqlQuery(s.sessionId, query, undefined, root, "resolvePointer");
       const doc = canonicalDoc(readBindings(result), "shimDoc");
-      if (doc) return doc;
+      if (doc) {
+        logStage("resolvePointer → 1 target: " + shortNuri(doc));
+        return doc;
+      }
     } catch (error) {
-      console.error("[storeRegistry] resolvePointer read failed:", error);
+      console.error(accessLogPrefix() + " resolvePointer failed:", error);
     }
     if (i < attempts - 1) {
       await sleep(step);
       step = Math.min(step * 2, maxStepMs);
     }
   }
+  logStage("resolvePointer → 0 targets");
   return "";
 }
 
@@ -355,7 +369,7 @@ async function writePointer(doc: Nuri): Promise<void> {
   try {
     await sparqlUpdate(s.sessionId, update, root, "writePointer");
   } catch (error) {
-    console.error("[storeRegistry] writePointer failed:", error);
+    console.error(accessLogPrefix() + " writePointer failed:", error);
   }
 }
 
@@ -394,6 +408,7 @@ async function resolveShimDoc(): Promise<Nuri> {
       // so a cold 0 on the doc-shim is authoritative (genuinely absent), not sync-lag.
       await ensureRepoOpen(existing);
       shimDocNuri = existing;
+      logStage("resolveShimDoc → " + shortNuri(existing));
       return existing;
     }
 
@@ -403,6 +418,7 @@ async function resolveShimDoc(): Promise<Nuri> {
     await writePointer(doc);
     await ensureRepoOpen(doc);
     shimDocNuri = doc;
+    logStage("resolveShimDoc → " + shortNuri(doc));
     return doc;
   })();
 
@@ -456,7 +472,7 @@ export async function loadShim(): Promise<Map<string, AccountRecord>> {
       accountCache.set(key, record);
     }
   } catch (error) {
-    console.error("[storeRegistry] loadShim failed:", error);
+    console.error(accessLogPrefix() + " loadShim failed:", error);
   }
   cache = map;
   return map;
@@ -502,16 +518,20 @@ export async function resolveAccount(id: string): Promise<AccountRecord | null>
   try {
     const result = await sparqlQuery(s.sessionId, query, undefined, doc, "resolveAccount");
     const rows = readBindings(result);
-    if (rows.length === 0) return null;
+    if (rows.length === 0) {
+      logStage("resolveAccount(" + key + ") → null");
+      return null;
+    }
     // DETERMINISTIC: a corrupted shim may return SEVERAL bindings for this one
     // account subject (duplicate scope-doc values from past forks). Pick the
     // canonical (lexicographically-smallest) doc per scope so writer and reader
     // always resolve the SAME docPublic (robustness against PAST fork residue).
     const record = recordFromRows(rows, id);
     accountCache.set(key, record);
+    logStage("resolveAccount(" + key + ") → 1 record");
     return record;
   } catch (error) {
-    console.error("[storeRegistry] resolveAccount failed:", error);
+    console.error(accessLogPrefix() + " resolveAccount failed:", error);
     return null;
   }
 }
@@ -542,7 +562,7 @@ async function writeRecord(doc: Nuri, record: AccountRecord): Promise<void> {
   try {
     await sparqlUpdate(s.sessionId, update, doc, "writeRecord");
   } catch (error) {
-    console.error("[storeRegistry] writeRecord persist failed:", error);
+    console.error(accessLogPrefix() + " writeRecord persist failed:", error);
   }
 }
 
@@ -733,7 +753,7 @@ export async function createEntityDoc(id: string, scope: Scope): Promise<Nuri> {
       "createEntityDoc",
     );
   } catch (error) {
-    console.error("[storeRegistry] createEntityDoc index append failed:", error);
+    console.error(accessLogPrefix() + " createEntityDoc index append failed:", error);
   }
   return entityNuri;
 }
@@ -765,8 +785,9 @@ async function readScopeIndex(indexDoc: Nuri): Promise<Nuri[]> {
       if (v) out.push(v);
     }
   } catch (error) {
-    console.error("[storeRegistry] readScopeIndex read failed:", error);
+    console.error(accessLogPrefix() + " readScopeIndex failed:", error);
   }
+  logStage("readScopeIndex(" + shortNuri(indexDoc) + ") → " + out.length + " entities");
   return out;
 }
 

packages/client/test/access-log.test.ts

@@ -6,9 +6,10 @@
  * (a) OFF by default: reads + writes via sparqlQuery / sparqlUpdate / docCreate
  *     emit nothing to console.log.
  * (b) ON via configure({ debugAccessLog: true }): each read/write emits a line
- *     matching `[polyfill] [<identity>] READ/WRITE <shortNuri> (<label>)` plus
- *     row-count suffix on READs. The NURI is shortened by shortNuri (did:ng:o:
- *     prefix + :v: suffix stripped, RepoID truncated to 8 chars + ellipsis).
+ *     matching `[<identity>][polyfill] READ/WRITE <shortNuri> (<label>)` (identity
+ *     FIRST, `[polyfill]` glued right after) plus row-count suffix on READs. The
+ *     NURI is shortened by shortNuri (did:ng:o: prefix + :v: suffix stripped,
+ *     RepoID truncated to 8 chars + ellipsis).
  * (c) ON via env var NG_EVENTUALLY_ACCESS_LOG=1: same behavior without changing
  *     calling code.
  * (d) Identity follows setCurrentUser: after setCurrentUser the prefix changes.
@@ -160,8 +161,7 @@ describe("access-log: ON via configure({ debugAccessLog: true })", () => {
       restore();
     }
     expect(lines.length).toBe(1);
-    expect(lines[0]).toMatch(/^\[polyfill\] /); // SDK-layer access-log prefix
-    expect(lines[0]).toMatch(/\[alice\]/);
+    expect(lines[0]).toMatch(/^\[alice\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
     expect(lines[0]).toMatch(/READ/);
     expect(lines[0]).toContain(shortNuri("did:ng:o:q")); // NURI shortened
     expect(lines[0]).not.toContain("did:ng:o:"); // full prefix stripped
@@ -179,8 +179,7 @@ describe("access-log: ON via configure({ debugAccessLog: true })", () => {
       restore();
     }
     expect(lines.length).toBe(1);
-    expect(lines[0]).toMatch(/^\[polyfill\] /);
-    expect(lines[0]).toMatch(/\[alice\]/);
+    expect(lines[0]).toMatch(/^\[alice\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
     expect(lines[0]).toMatch(/WRITE/);
     expect(lines[0]).toContain(shortNuri("did:ng:o:w"));
     expect(lines[0]).toMatch(/writeLabel/);
@@ -196,8 +195,7 @@ describe("access-log: ON via configure({ debugAccessLog: true })", () => {
       restore();
     }
     expect(lines.length).toBe(1);
-    expect(lines[0]).toMatch(/^\[polyfill\] /);
-    expect(lines[0]).toMatch(/\[alice\]/);
+    expect(lines[0]).toMatch(/^\[alice\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
     expect(lines[0]).toMatch(/WRITE/);
     // The nuri is the value returned by ng.doc_create, shortened by shortNuri.
     expect(lines[0]).toContain(shortNuri("did:ng:o:log-doc"));
@@ -223,8 +221,7 @@ describe("access-log: ON via env var NG_EVENTUALLY_ACCESS_LOG=1", () => {
       restore();
     }
     expect(lines.length).toBe(1);
-    expect(lines[0]).toMatch(/^\[polyfill\] /);
-    expect(lines[0]).toMatch(/\[bob\]/);
+    expect(lines[0]).toMatch(/^\[bob\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
     expect(lines[0]).toMatch(/READ/);
     expect(lines[0]).toContain(shortNuri("did:ng:o:env-q"));
   });
@@ -241,7 +238,7 @@ describe("access-log: ON via env var NG_EVENTUALLY_ACCESS_LOG=1", () => {
       restore();
     }
     expect(lines.length).toBe(1);
-    expect(lines[0]).toMatch(/\[charlie\]/);
+    expect(lines[0]).toMatch(/^\[charlie\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
     expect(lines[0]).toMatch(/WRITE/);
   });
 
@@ -266,8 +263,8 @@ describe("access-log: identity follows setCurrentUser", () => {
       restore();
     }
     expect(lines.length).toBe(2);
-    expect(lines[0]).toMatch(/\[first-user\]/);
-    expect(lines[1]).toMatch(/\[second-user\]/);
+    expect(lines[0]).toMatch(/^\[first-user\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
+    expect(lines[1]).toMatch(/^\[second-user\]\[polyfill\] /);
   });
 
   it("prefix is (none) when no identity is set", async () => {
@@ -280,6 +277,6 @@ describe("access-log: identity follows setCurrentUser", () => {
       restore();
     }
     expect(lines.length).toBe(1);
-    expect(lines[0]).toMatch(/\[\(none\)\]/);
+    expect(lines[0]).toMatch(/^\[\(none\)\]\[polyfill\] /); // identity-first, glued [polyfill] prefix
   });
 });