diff --git a/src/server.ts b/src/server.ts index 956114d..9a5d3b6 100644 --- a/src/server.ts +++ b/src/server.ts @@ -64,7 +64,7 @@ import { flushCache, startBackgroundInit, } from "./services/startup.js"; -import { checkWritePath } from "./services/write-health.js"; +import { checkWritePathWithTimeout, getLastWritePathVerdict, formatWritePathLine } from "./services/write-health.js"; import { getEffectTracker } from "./services/effect-tracker.js"; import { RIPPLE, ANSI } from "./services/display-protocol.js"; import { getProject } from "./services/session-state.js"; @@ -371,9 +371,13 @@ export function createServer(): Server { const tracker = getEffectTracker(); const report = tracker.getHealthReport(failureLimit); const summary = tracker.formatSummary(); + // GIT-102: the startup write-path verdict, including "timed out, + // durability UNVERIFIED" — previously visible only on stderr, if at all. + const writePath = getLastWritePathVerdict(); result = { ...report, - text: summary || "No tracked effects this session.", + write_path: writePath, + text: `${formatWritePathLine(writePath)}\n\n${summary || "No tracked effects this session."}`, }; break; } @@ -501,14 +505,14 @@ export async function runServer(): Promise { } // Verify the write path with the FINAL tier (post-validation): catches an // invalid license silently downgrading writes to local files. - void checkWritePath(); + void checkWritePathWithTimeout(); // GIT-102: bounded; verdict kept for health }).catch((err) => { console.error(`[gitmem:license] Validation error: ${err}`); }); } else { // No license key to validate — verify the write path with the detected tier // (catches a GITMEM_TABLE_PREFIX / schema mismatch on the backward-compat path). - void checkWritePath(); + void checkWritePathWithTimeout(); // GIT-102: bounded; verdict kept for health } if (hasSupabase()) { diff --git a/src/services/write-health.ts b/src/services/write-health.ts index a424d76..40500d0 100644 --- a/src/services/write-health.ts +++ b/src/services/write-health.ts @@ -17,6 +17,12 @@ * Fire-and-forget: never throws (whole body is guarded), never blocks startup. * Logs a loud warning to stderr when misconfigured, a one-line confirmation * otherwise. + * + * GIT-102: the probe had no timeout. A store that accepts the connection and + * never answers left it pending forever — no warning, no confirmation, and + * nothing anywhere saying durability had not been checked. The server now runs + * it through checkWritePathWithTimeout(): raced against 10 s, with a + * "timed_out" verdict that says so, and the last verdict kept for `health`. */ import { getTier, hasSupabase, getTablePrefix, getTableName } from "./tier.js"; @@ -30,12 +36,115 @@ export type WritePathMode = | "free_with_credentials" // creds present but tier free — writes silently local (bug) | "missing_tables" // pro/dev but resolved tables absent (bug) | "supabase" // healthy: pro/dev with tables present - | "skipped"; // unexpected internal error — stayed silent, did not block startup + | "skipped" // unexpected internal error — stayed silent, did not block startup + | "timed_out" // GIT-102: no answer within the budget — durability UNVERIFIED + | "unreachable"; // GIT-102: probes errored (network/auth) — durability UNVERIFIED export interface WritePathResult { ok: boolean; mode: WritePathMode; missing?: string[]; + /** unreachable: the probe error, as the store reported it. */ + error?: string; +} + +/** The most recent write-path verdict, for `health` (GIT-102). */ +export interface WritePathVerdict extends WritePathResult { + /** One line a person can act on. */ + summary: string; + checked_at: string; + duration_ms: number; + /** A check that finished after its timeout had already been reported. */ + late?: boolean; +} + +export const WRITE_PATH_TIMEOUT_MS = 10_000; + +let lastVerdict: WritePathVerdict | null = null; + +/** The last write-path verdict, or null when no check has finished or timed out yet. */ +export function getLastWritePathVerdict(): WritePathVerdict | null { + return lastVerdict; +} + +/** For tests. */ +export function resetWritePathVerdict(): void { + lastVerdict = null; +} + +/** The `health` line for a verdict (GIT-102). */ +export function formatWritePathLine(v: WritePathVerdict | null): string { + if (!v) return "Write path: not checked yet (the startup check has not finished or timed out)"; + return `Write path: ${v.summary} (${v.ok ? "ok" : "NOT OK"}, checked ${v.checked_at}, ${v.duration_ms} ms` + + `${v.late ? ", finished after its timeout" : ""})`; +} + +function summarize(r: WritePathResult, timeoutMs: number): string { + switch (r.mode) { + case "supabase": return "Supabase — learnings/decisions tables present, writes are durable"; + case "local": return "local files (free tier, no Supabase configured) — intended"; + case "free_with_credentials": return "Supabase is configured but the tier resolved to FREE — writes are going to local files, NOT Supabase"; + case "missing_tables": return `tables missing on the Supabase backend (${(r.missing || []).join(", ")}) — create_learning / create_decision will fail`; + case "skipped": return "check skipped after an internal error — durability UNVERIFIED"; + case "timed_out": return `timed out after ${Math.round(timeoutMs / 1000)} s, durability UNVERIFIED`; + case "unreachable": return `store unreachable (${r.error ?? "probe failed"}), durability UNVERIFIED`; + } +} + +/** + * Run checkWritePath() against a deadline and record the verdict. + * + * Resolves by the deadline at the latest. If the check finishes afterwards, + * its real verdict replaces "timed_out" (marked late) — the store answered + * slowly, and the latest word on it is the one health should show. + */ +export async function checkWritePathWithTimeout( + timeoutMs: number = WRITE_PATH_TIMEOUT_MS, + check: () => Promise = checkWritePath +): Promise { + const started = Date.now(); + let timedOut = false; + let timer: ReturnType | undefined; + + const record = (r: WritePathResult, late = false): WritePathVerdict => { + lastVerdict = { + ...r, + summary: summarize(r, timeoutMs), + checked_at: new Date().toISOString(), + duration_ms: Date.now() - started, + ...(late && { late: true }), + }; + return lastVerdict; + }; + + const checked = check().then((r) => { + if (timedOut) { + const v = record(r, true); + console.error(`[gitmem] Write-path check finished late (${v.duration_ms} ms): ${v.summary}`); + return v; + } + return record(r); + }); + + const deadline = new Promise((resolve) => { + timer = setTimeout(() => { + timedOut = true; + const v = record({ ok: false, mode: "timed_out" }); + console.error( + `\n\u26a0\ufe0f [gitmem] WRITE PATH: ${v.summary}.\n` + + " The Supabase store did not answer the write-path probe. Writes may or may not be landing;\n" + + " check connectivity to SUPABASE_URL. `health` shows the latest verdict.\n" + ); + resolve(v); + }, timeoutMs); + timer.unref?.(); + }); + + try { + return await Promise.race([checked, deadline]); + } finally { + if (timer) clearTimeout(timer); + } } export async function checkWritePath(): Promise { @@ -65,6 +174,7 @@ export async function checkWritePath(): Promise { const prefix = getTablePrefix(); const prefixSource = process.env.GITMEM_TABLE_PREFIX ? "GITMEM_TABLE_PREFIX" : "default"; const missing: string[] = []; + const probeErrors: string[] = []; for (const base of ["learnings", "decisions"]) { const table = getTableName(base); @@ -73,7 +183,9 @@ export async function checkWritePath(): Promise { } catch (err) { const msg = err instanceof Error ? err.message : String(err); if (SCHEMA_MISS.test(msg)) missing.push(table); - // Transient network/auth errors are out of scope for this check. + // GIT-102: a network/auth error used to be ignored here, so a store + // that refused every connection was reported as "Write-path OK". + else probeErrors.push(`${table}: ${msg}`); } } @@ -89,6 +201,15 @@ export async function checkWritePath(): Promise { return { ok: false, mode: "missing_tables", missing }; } + if (probeErrors.length > 0) { + const error = probeErrors.join("; ").slice(0, 300); + console.error( + "\n\u26a0\ufe0f [gitmem] WRITE PATH: the Supabase store could not be probed — durability UNVERIFIED.\n" + + ` ${error}\n` + ); + return { ok: false, mode: "unreachable", error }; + } + console.error( `[gitmem] Write-path OK (tier ${getTier()}, prefix "${prefix}", learnings/decisions present).` ); diff --git a/src/tools/session-close.ts b/src/tools/session-close.ts index 2388a4c..b955b5f 100644 --- a/src/tools/session-close.ts +++ b/src/tools/session-close.ts @@ -329,7 +329,7 @@ async function sessionCloseFree( clearCurrentSession(); const latencyMs = timer.stop(); const perfData = buildPerformanceData("session_close", latencyMs, 0); - const errorDisplay = formatCloseDisplay(sessionId, closeCompliance, params, learningsCount, false, [`Failed to persist session: ${errorMessage}`]); + const errorDisplay = formatCloseDisplay(sessionId, closeCompliance, params, learningsCount, false, [`Failed to persist session: ${errorMessage}`], undefined, undefined, false); return { success: false, @@ -363,6 +363,8 @@ function formatCloseDisplay( errors?: string[], transcriptStatus?: TranscriptStatus, blindspotSnippet?: string | null, + /** GIT-102: whether the session content itself landed; defaults to `success`. */ + sessionStored: boolean = success, ): string { const lines: string[] = []; @@ -434,15 +436,55 @@ function formatCloseDisplay( } // Write health — only on failure - const healthReport = getEffectTracker().getHealthReport(); - if (healthReport.overall.failed > 0) { + const warnings = formatWriteWarnings(getEffectTracker().getHealthReport(), sessionStored); + if (warnings.length > 0) { lines.push(""); - lines.push(`${STATUS.warn} ${healthReport.overall.failed} write failure${healthReport.overall.failed > 1 ? "s" : ""}`); + for (const w of warnings) lines.push(`${STATUS.warn} ${w}`); } return wrapDisplay(lines.join("\n")); } +/** GIT-102: what each tracked write path is, in words. */ +const SUBSYSTEM_NAMES: Record = { + triple_write: "knowledge graph (triples)", + embedding: "session embedding", + scar_usage: "scar usage records", + transcript: "transcript upload", + metrics: "query metrics", + relevance_update: "relevance feedback", + variant_generation: "scar variants", + cache_set: "local cache", +}; + +/** + * GIT-102: one self-describing line per failing write subsystem. + * + * The close used to print "WARN 3 write failures" and nothing else: not which + * writes, not why, and — the question every reader actually has — not whether + * the session itself was saved. Each line now names the subsystem, the cause + * (its most recent error), and states whether the session content was stored. + * That last clause is mandatory on every line, so no WARN can be read as + * "the close failed" when it didn't, or as harmless when it wasn't. + */ +export function formatWriteWarnings( + report: ReturnType["getHealthReport"]>, + sessionStored: boolean +): string[] { + const where = hasSupabase() ? "" : " (local)"; + const stored = sessionStored ? `session content stored OK${where}` : "session content NOT stored"; + const lines: string[] = []; + for (const [path, s] of Object.entries(report.byPath)) { + if (s.failed === 0) continue; + const name = SUBSYSTEM_NAMES[path] ?? path; + const cause = s.lastFailure?.error + ? truncate(s.lastFailure.error.replace(/\s+/g, " ").trim(), 160) + : "no error message recorded"; + lines.push(`${name}: ${s.failed} of ${s.attempted} write${s.attempted > 1 ? "s" : ""} failed — ${cause} · ${stored}`); + } + return lines; +} + /** * GIT-21: Clean up all session files for a closed session. * Unregisters from registry, deletes per-session directory, and removes legacy file. @@ -932,6 +974,9 @@ export async function sessionClose( // This keeps the visible MCP tool call small: just session_id + close_type. const payloadPath = getGitmemPath("closing-payload.json"); let payloadConsumed = false; + // Whether the session row reached the durable store (GIT-102: the close + // display says so on every WARN; set only after the upsert resolves). + let sessionRowStored = false; try { if (fs.existsSync(payloadPath)) { const filePayload = JSON.parse(fs.readFileSync(payloadPath, "utf-8")) as Partial; @@ -1470,6 +1515,7 @@ export async function sessionClose( supabase.directUpsert(sessionsTable, sessionRow), blindspotPromise, ]); + sessionRowStored = true; // Tracked fire-and-forget embedding generation + session update + thread detection if (isEmbeddingAvailable()) { @@ -1642,7 +1688,8 @@ export async function sessionClose( const allErrors = [...persistErrors, ...coverageWarnings, ...validation.warnings]; - const display = formatCloseDisplay(sessionId, closeCompliance, params, learningsCount, !partialPersist, allErrors.length > 0 ? allErrors : undefined, transcriptStatus, blindspotSnippet); + // The session row is upserted above; a partial persist is threads, not the session. + const display = formatCloseDisplay(sessionId, closeCompliance, params, learningsCount, !partialPersist, allErrors.length > 0 ? allErrors : undefined, transcriptStatus, blindspotSnippet, true); return { success: !partialPersist, @@ -1660,7 +1707,7 @@ export async function sessionClose( // Clear session state even on error (session is done either way) clearCurrentSession(); - const errorDisplay = formatCloseDisplay(sessionId, closeCompliance, params, learningsCount, false, [`Failed to persist session: ${errorMessage}`], transcriptStatus, blindspotSnippet); + const errorDisplay = formatCloseDisplay(sessionId, closeCompliance, params, learningsCount, false, [`Failed to persist session: ${errorMessage}`], transcriptStatus, blindspotSnippet, sessionRowStored); return { success: false, diff --git a/tests/e2e/blank-supabase.mjs b/tests/e2e/blank-supabase.mjs index 84b343b..98afedc 100644 --- a/tests/e2e/blank-supabase.mjs +++ b/tests/e2e/blank-supabase.mjs @@ -377,6 +377,12 @@ async function flow() { await waitQuiet(netlog, { minMs: 2000, quietMs: 3000 }); const health = await step("health", { failure_limit: 20 }); + // GIT-102: every WARN on the close names a subsystem and cause and says + // whether the session content was stored; health reports the write-path verdict. + const closeWarns = sc.replace(/\x1b\[[0-9;]*m/g, "").split("\n").filter((l) => /^WARN /.test(l)); + const closeWarnsSelfDescribing = closeWarns.every((l) => /^WARN .+: \d+ of \d+ writes? failed — .+ · session content (stored OK|NOT stored)/.test(l)); + const healthHasWritePath = /^Write path: /m.test(health); + // Did the close land? Is relevance readable from the store (GIT-109)? const closedRows = sessionId ? await rest("GET", `gitmem_sessions?select=id,closing_reflection&id=eq.${sessionId}`, undefined, { Prefer: "" }).then((r) => r.json()) @@ -408,6 +414,9 @@ async function flow() { remote_sessions_after: await count("gitmem_sessions"), remote_scar_usage_after: await count("gitmem_scar_usage"), session_close_persisted: closedRows.length === 1 && closedRows[0].closing_reflection != null, + close_warns: closeWarns, + close_warns_self_describing: closeWarnsSelfDescribing, + health_has_write_path: healthHasWritePath, relevance_readable: relevance.some((r) => scarIds.some((id) => (r.memories_applied || []).includes(id) && r.memory_relevance?.[id])), relevance, health_failed_total: failed, @@ -520,6 +529,12 @@ const failureCheck = checkFailures(allVenueRequests); const edgeCalls = allVenueRequests.filter((r) => r.path.startsWith("/functions/v1/")) .map((r) => `${r.method} ${r.path} -> ${r.status}`); if (edgeCalls.length) failureCheck.unexpected.push(...edgeCalls.map((c) => `edge function called (GIT-97): ${c}`)); +if (mode === "flow" && !result.close_warns_self_describing) { + failureCheck.unexpected.push(`session_close WARN is not self-describing (GIT-102): ${result.close_warns.join(" | ")}`); +} +if (mode === "flow" && !result.health_has_write_path) { + failureCheck.unexpected.push("health does not report the write-path verdict (GIT-102)"); +} if (mode === "flow" && !result.session_close_persisted) { failureCheck.unexpected.push(`session_close did not persist session ${result.session_id} (closing_reflection missing)`); } diff --git a/tests/unit/services/write-health-probe.test.ts b/tests/unit/services/write-health-probe.test.ts new file mode 100644 index 0000000..b3e7b8a --- /dev/null +++ b/tests/unit/services/write-health-probe.test.ts @@ -0,0 +1,48 @@ +/** + * GIT-102: checkWritePath's verdicts, store mocked at the client. + * + * A probe that errors for any reason other than a missing table used to be + * ignored, so a store refusing every connection was reported "Write-path OK". + */ +import { describe, it, expect, vi, beforeEach } from "vitest"; + +const probe = vi.hoisted(() => ({ impl: async (): Promise => [] })); + +vi.mock("../../../src/services/supabase-client.js", () => ({ + isConfigured: () => true, + directQuery: vi.fn(() => probe.impl()), +})); +vi.mock("../../../src/services/tier.js", () => ({ + getTier: () => "pro", + hasSupabase: () => true, + getTablePrefix: () => "gitmem_", + getTableName: (b: string) => `gitmem_${b}`, +})); + +import { checkWritePath } from "../../../src/services/write-health.js"; + +beforeEach(() => { probe.impl = async () => []; }); + +describe("checkWritePath verdicts (GIT-102)", () => { + it("tables answer: supabase, ok", async () => { + expect(await checkWritePath()).toEqual({ ok: true, mode: "supabase" }); + }); + + it("a missing table: missing_tables", async () => { + probe.impl = async () => { throw new Error("PGRST205 Could not find the table"); }; + expect(await checkWritePath()).toMatchObject({ ok: false, mode: "missing_tables", missing: ["gitmem_learnings", "gitmem_decisions"] }); + }); + + it("the store refuses the connection: unreachable, NOT ok (was: Write-path OK)", async () => { + probe.impl = async () => { throw new TypeError("fetch failed: ECONNREFUSED"); }; + const r = await checkWritePath(); + expect(r.ok).toBe(false); + expect(r.mode).toBe("unreachable"); + expect(r.error).toContain("ECONNREFUSED"); + }); + + it("an auth failure is unreachable too, not OK", async () => { + probe.impl = async () => { throw new Error("Supabase query error: 401 - Invalid API key"); }; + expect(await checkWritePath()).toMatchObject({ ok: false, mode: "unreachable" }); + }); +}); diff --git a/tests/unit/services/write-health-timeout.test.ts b/tests/unit/services/write-health-timeout.test.ts new file mode 100644 index 0000000..b573ab7 --- /dev/null +++ b/tests/unit/services/write-health-timeout.test.ts @@ -0,0 +1,111 @@ +/** + * GIT-102: diagnostics that say what they know and what they don't. + * + * 1. The startup write-path probe is raced against a deadline. A store that + * never answers yields "timed out, durability UNVERIFIED" — not silence. + * The last verdict is kept for `health`, and a late answer replaces it. + * 2. session_close's WARN names the subsystem, the cause, and always whether + * the session content itself was stored. + */ +import { describe, it, expect, beforeEach } from "vitest"; +import { + checkWritePathWithTimeout, + getLastWritePathVerdict, + resetWritePathVerdict, + formatWritePathLine, + WRITE_PATH_TIMEOUT_MS, +} from "../../../src/services/write-health.js"; +import type { WritePathResult } from "../../../src/services/write-health.js"; +import { formatWriteWarnings } from "../../../src/tools/session-close.js"; + +const never = () => new Promise(() => {}); +const after = (ms: number, r: WritePathResult) => () => new Promise((res) => setTimeout(() => res(r), ms)); + +beforeEach(() => resetWritePathVerdict()); + +describe("write-path check timeout (GIT-102)", () => { + it("defaults to a 10 s budget", () => { + expect(WRITE_PATH_TIMEOUT_MS).toBe(10_000); + }); + + it("a probe that never answers resolves at the deadline as timed_out, durability UNVERIFIED", async () => { + const t0 = Date.now(); + const v = await checkWritePathWithTimeout(60, never); + expect(Date.now() - t0).toBeLessThan(1000); + expect(v.ok).toBe(false); + expect(v.mode).toBe("timed_out"); + expect(v.summary).toMatch(/timed out after .* durability UNVERIFIED/); + expect(getLastWritePathVerdict()?.mode).toBe("timed_out"); + }); + + it("names the configured budget in seconds", async () => { + const v = await checkWritePathWithTimeout(10_000, () => Promise.resolve({ ok: false, mode: "timed_out" })); + expect(v.summary).toBe("timed out after 10 s, durability UNVERIFIED"); + }); + + it("a fast probe's verdict is recorded as-is", async () => { + const v = await checkWritePathWithTimeout(1000, () => Promise.resolve({ ok: true, mode: "supabase" })); + expect(v.mode).toBe("supabase"); + expect(v.late).toBeUndefined(); + expect(getLastWritePathVerdict()).toEqual(v); + }); + + it("a probe that answers after the deadline replaces timed_out, marked late", async () => { + const v = await checkWritePathWithTimeout(30, after(90, { ok: false, mode: "missing_tables", missing: ["gitmem_learnings"] })); + expect(v.mode).toBe("timed_out"); + await new Promise((r) => setTimeout(r, 120)); + const latest = getLastWritePathVerdict()!; + expect(latest.mode).toBe("missing_tables"); + expect(latest.late).toBe(true); + expect(latest.summary).toContain("gitmem_learnings"); + }); + + it("health's line says not-checked, UNVERIFIED, or ok — never nothing", async () => { + expect(formatWritePathLine(null)).toMatch(/not checked yet/); + const timedOut = await checkWritePathWithTimeout(20, never); + expect(formatWritePathLine(timedOut)).toMatch(/^Write path: timed out after .* durability UNVERIFIED \(NOT OK, checked /); + const ok = await checkWritePathWithTimeout(1000, () => Promise.resolve({ ok: true, mode: "supabase" })); + expect(formatWritePathLine(ok)).toMatch(/^Write path: Supabase — .* \(ok, checked /); + }); +}); + +describe("session_close WARN lines (GIT-102)", () => { + const report = (byPath: Record) => ({ + byPath: Object.fromEntries(Object.entries(byPath).map(([k, v]) => [k, { + attempted: v.attempted, succeeded: v.attempted - v.failed, failed: v.failed, successRate: "", avgDurationMs: 0, + ...(v.error && { lastFailure: { error: v.error, timestamp: "" } }), + }])), + overall: { attempted: 0, succeeded: 0, failed: 0, successRate: "", paths_with_failures: [] }, + recentFailures: [], + uptimeMs: 0, + }); + + it("names subsystem and cause, and says the session content was stored", () => { + const lines = formatWriteWarnings(report({ + triple_write: { attempted: 3, failed: 3, error: 'POST knowledge_triples 400: invalid input syntax for type uuid: "t-abc"' }, + embedding: { attempted: 1, failed: 0 }, + }), true); + expect(lines).toHaveLength(1); + expect(lines[0]).toMatch(/^knowledge graph \(triples\): 3 of 3 writes failed — POST knowledge_triples 400: invalid input syntax/); + expect(lines[0]).toMatch(/· session content stored OK( \(local\))?$/); + }); + + it("says NOT stored when the session row did not land — on every line", () => { + const lines = formatWriteWarnings(report({ + triple_write: { attempted: 1, failed: 1, error: "boom" }, + transcript: { attempted: 1, failed: 1, error: "bucket missing" }, + }), false); + expect(lines).toHaveLength(2); + for (const l of lines) expect(l).toMatch(/· session content NOT stored$/); + expect(lines[1]).toMatch(/^transcript upload: 1 of 1 write failed — bucket missing/); + }); + + it("an unknown subsystem is named by its path, a missing cause is said to be missing", () => { + const [line] = formatWriteWarnings(report({ new_path: { attempted: 2, failed: 1 } }), true); + expect(line).toMatch(/^new_path: 1 of 2 writes failed — no error message recorded · session content stored OK/); + }); + + it("no failures, no WARN", () => { + expect(formatWriteWarnings(report({ triple_write: { attempted: 2, failed: 0 } }), true)).toEqual([]); + }); +});