feat(E1b.8): persistent rotated log + flagsSchemaVersion startup migration
The last E1b story. Every auto-sync decision is durably logged (NFR-5), and old
seeded notes are stamped with the current flags schema version at startup
before auto-sync engages (NFR-11) — so the controller can reason about which
notes carry the dual (contentHash + ccHash) baseline.
- src/server.ts persistent log: log() writes a JSON-line
{time,level,name,status,message} to <outDir>/logs/sync-<YYYY-MM-DD>.log via a
WriteStream, alongside the in-memory events (the dashboard's fast poll). Daily
rotation (date change → close+open) + size rotation (10MB → rename to
sync-<date>.<n>.log + reopen). pruneOldLogs at startup deletes logs/sync-*.log
older than AUTOSYNC_LOG_RETAIN_DAYS (14). Gated by foundryGuardEnabled (off →
in-memory only). startServer prunes + opens the log.
- src/server.ts flagsSchemaVersion: baselineFoundryBlock/baselineNote stamp
foundry.flagsSchemaVersion (FLAGS_SCHEMA_VERSION from E0.3) on every baseline.
stampFlagsSchemaVersion() (used by the migration) touches ONLY flagsSchemaVersion
— no contentHash/ccHash change, so it doesn't falsely trigger a push.
- src/server.ts migrateFlagsSchemaVersion(): startup pass walks index.matched,
stamps notes whose foundry.flagsSchemaVersion is absent/older (idempotent —
already-current notes skipped), in-flight-safe (mtime changes between read and
write → skip + log "in-flight edit"), logged to the persistent log. Runs BEFORE
auto-sync is allowed to start. status() exposes migrationCount/migrationRan/
schemaVersion.
- src/dashboard.html: "Migrated N notes to flagsSchemaVersion <v>" banner
(dismissible, shown once on first poll when migrationRan && migrationCount>0).
- tests/e1b8-log-migration.test.ts: 7 tests — log() writes a JSON-line (info +
error levels); pruneOldLogs runs without error; a clean push stamps
flagsSchemaVersion; migration stamps absent notes idempotently with NO
contentHash/ccHash change; already-current notes left alone; status exposes
migrationCount + schemaVersion.
tsc clean; 161 passing project-wide (18 pre-existing fixture-missing unchanged).
Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
@@ -92,6 +92,7 @@
|
||||
<button id="autoSyncBtn" onclick="toggleAutosync()" title="Toggle Obsidian→Foundry auto-sync. ON = saving a linked, seeded note in your vault pushes it into LIVE Foundry instantly (guarded by the note's foundry.contentHash baseline, so no-op saves and the post-push baseline write don't re-push; unlinked/unseeded notes are skipped). Foundry→Obsidian is NOT auto — use Sync / Re-pull for that. Needs the relay (RELAY_API_KEY). Dev mode baselines land in the --out mirror; apply mode in the real vault.">Auto-sync: off</button>
|
||||
</header>
|
||||
<div id="devBanner" class="badge warn" style="display:none;margin:6px 12px;padding:6px 10px">Dev mode — auto-sync disabled; pushes would target the --out mirror, not live Foundry. Start the server with --apply to enable.</div>
|
||||
<div id="migrationBanner" class="badge ok" style="display:none;margin:6px 12px;padding:6px 10px;cursor:pointer" title="Click to dismiss. The startup migration stamped foundry.flagsSchemaVersion on notes that lacked it (contentHash/ccHash untouched)."></div>
|
||||
<details id="autoSyncPanel" class="autosync-panel" open style="display:none;margin:0 12px;border-top:1px solid #ddd;padding:6px 12px;background:#fafafa">
|
||||
<summary style="cursor:pointer">Auto-sync activity <span id="autoSyncCounts" class="meta"></span><span id="autoSyncNote" class="meta" style="margin-left:8px"></span></summary>
|
||||
<div id="revertBar" style="margin:6px 0;display:none"><button id="revertBtn" class="bad" onclick="revertLastPush()" title="Restore Foundry to the state captured BEFORE the most recent auto-sync push (a full /update), then re-baseline the note. Use this to undo a wrong push."></button></div>
|
||||
@@ -125,7 +126,7 @@
|
||||
<section class="detail" id="detail">Select a row to inspect.</section>
|
||||
</main>
|
||||
<script>
|
||||
let INDEX = null, STATUS = null, SEL = null, REC_FILTER = null, AUTO = null, autoPoll = null;
|
||||
let INDEX = null, STATUS = null, SEL = null, REC_FILTER = null, AUTO = null, autoPoll = null, migrationDismissed = false;
|
||||
const dryEl = () => document.getElementById('dryRun');
|
||||
|
||||
// Recommendation -> display label, badge class, bulk op, and one-line guidance.
|
||||
@@ -359,6 +360,15 @@ async function refreshAutosync(){
|
||||
: '(no activity yet — save a linked, seeded note in your vault to trigger a push)';
|
||||
if (r.enabled && !autoPoll) autoPoll = setInterval(refreshAutosync, 2000);
|
||||
if (!r.enabled && autoPoll) { clearInterval(autoPoll); autoPoll = null; }
|
||||
// E1b.8: flagsSchemaVersion migration banner (shown once after start, dismissible).
|
||||
const migBanner = document.getElementById('migrationBanner');
|
||||
if (r.migrationRan && r.migrationCount > 0 && !migrationDismissed) {
|
||||
migBanner.textContent = `Migrated ${r.migrationCount} note${r.migrationCount > 1 ? 's' : ''} to flagsSchemaVersion ${r.schemaVersion} (foundry.flagsSchemaVersion stamped; contentHash/ccHash untouched) — click to dismiss`;
|
||||
migBanner.style.display = '';
|
||||
migBanner.onclick = () => { migrationDismissed = true; migBanner.style.display = 'none'; };
|
||||
} else {
|
||||
migBanner.style.display = 'none';
|
||||
}
|
||||
// E1b.4: "Revert last push" button — shown when there's a recent push and
|
||||
// the guard is on (revert is meaningless without the per-uuid backups).
|
||||
const revertBar = document.getElementById('revertBar');
|
||||
|
||||
193
src/server.ts
193
src/server.ts
@@ -9,8 +9,8 @@
|
||||
// unless the server was started with --apply.
|
||||
|
||||
import { createServer, type IncomingMessage, type ServerResponse, type Server } from "node:http";
|
||||
import { readFile, writeFile, mkdir, copyFile, access, stat, readdir, unlink } from "node:fs/promises";
|
||||
import { watch, readdirSync, statSync, type FSWatcher } from "node:fs";
|
||||
import { readFile, writeFile, mkdir, copyFile, access, stat, readdir, unlink, rename } from "node:fs/promises";
|
||||
import { watch, readdirSync, statSync, mkdirSync, existsSync, createWriteStream, type WriteStream, type FSWatcher } from "node:fs";
|
||||
import { join, dirname, relative, basename, extname } from "node:path";
|
||||
import { fileURLToPath } from "node:url";
|
||||
import { JournalDb } from "./db.js";
|
||||
@@ -22,6 +22,7 @@ import { splitFrontmatter, readFoundryBlock } from "./frontmatter.js";
|
||||
import { contentHash } from "./normalize.js";
|
||||
import { SyncLock, relPathLockKey } from "./synclock.js";
|
||||
import { ccHash } from "./cchash.js";
|
||||
import { FLAGS_SCHEMA_VERSION } from "./schema-version.js";
|
||||
import { backupStamp } from "./write.js";
|
||||
import type { RelayConfig, FoundryHostConfig } from "./config.js";
|
||||
import type { Mode, JournalEntry } from "./types.js";
|
||||
@@ -358,25 +359,28 @@ interface PushAllItem {
|
||||
logs?: string[];
|
||||
}
|
||||
|
||||
/** Rewrite the foundry: block's contentHash + syncedAt (+ ccHash when provided)
|
||||
* in-place (text surgery; leaves cc_uuid/cc_type/folder_path and all curation
|
||||
* untouched). Mirrors resync.ts. E1b.2: if `newCcHash` is provided, rewrites
|
||||
* the `ccHash:` line (adding it if absent) so the next save's divergence guard
|
||||
* compares against the post-push Foundry state. */
|
||||
function baselineFoundryBlock(md: string, newHash: string, newSyncedAt: string, newCcHash?: string): string {
|
||||
/** Rewrite the foundry: block's contentHash + syncedAt (+ ccHash when provided,
|
||||
* + flagsSchemaVersion when provided) in-place (text surgery; leaves
|
||||
* cc_uuid/cc_type/folder_path and all curation untouched). Mirrors resync.ts.
|
||||
* E1b.2: if `newCcHash` is provided, rewrites the `ccHash:` line (adding it if
|
||||
* absent) so the next save's divergence guard compares against the post-push
|
||||
* Foundry state. E1b.8: if `newSchemaVersion` is provided, stamps the
|
||||
* `flagsSchemaVersion:` line (adding it if absent). */
|
||||
function baselineFoundryBlock(md: string, newHash: string, newSyncedAt: string, newCcHash?: string, newSchemaVersion?: string): string {
|
||||
const lines = md.split(/\n/);
|
||||
let i = 0;
|
||||
while (i < lines.length && lines[i] !== "foundry:") i++;
|
||||
if (i >= lines.length) return md;
|
||||
i++;
|
||||
let changed = false;
|
||||
// Track whether a ccHash line exists in the block so we can append one if not.
|
||||
let ccHashLineIdx = -1;
|
||||
let schemaLineIdx = -1;
|
||||
let blockEnd = i; // index after the last ` `-prefixed line in the block
|
||||
while (i < lines.length && lines[i].startsWith(" ")) {
|
||||
if (lines[i].startsWith(" contentHash:")) { lines[i] = ` contentHash: ${newHash}`; changed = true; }
|
||||
else if (lines[i].startsWith(" syncedAt:")) { lines[i] = ` syncedAt: ${newSyncedAt}`; changed = true; }
|
||||
else if (lines[i].startsWith(" ccHash:")) { ccHashLineIdx = i; }
|
||||
else if (lines[i].startsWith(" flagsSchemaVersion:")) { schemaLineIdx = i; }
|
||||
blockEnd = i + 1;
|
||||
i++;
|
||||
}
|
||||
@@ -384,26 +388,59 @@ function baselineFoundryBlock(md: string, newHash: string, newSyncedAt: string,
|
||||
if (ccHashLineIdx >= 0) {
|
||||
if (lines[ccHashLineIdx] !== ` ccHash: ${newCcHash}`) { lines[ccHashLineIdx] = ` ccHash: ${newCcHash}`; changed = true; }
|
||||
} else {
|
||||
// Insert a ccHash line at the end of the foundry: block.
|
||||
lines.splice(blockEnd, 0, ` ccHash: ${newCcHash}`);
|
||||
changed = true;
|
||||
}
|
||||
}
|
||||
if (newSchemaVersion !== undefined) {
|
||||
if (schemaLineIdx >= 0) {
|
||||
if (lines[schemaLineIdx] !== ` flagsSchemaVersion: ${newSchemaVersion}`) { lines[schemaLineIdx] = ` flagsSchemaVersion: ${newSchemaVersion}`; changed = true; }
|
||||
} else {
|
||||
lines.splice(blockEnd, 0, ` flagsSchemaVersion: ${newSchemaVersion}`);
|
||||
changed = true;
|
||||
}
|
||||
}
|
||||
return changed ? lines.join("\n") : md;
|
||||
}
|
||||
|
||||
/** E1b.8: stamp ONLY the foundry.flagsSchemaVersion line (leaving contentHash,
|
||||
* syncedAt, ccHash untouched). Used by the startup migration so it doesn't
|
||||
* falsely trigger a push (no contentHash/ccHash change). */
|
||||
function stampFlagsSchemaVersion(md: string, version: string): string {
|
||||
const lines = md.split(/\n/);
|
||||
let i = 0;
|
||||
while (i < lines.length && lines[i] !== "foundry:") i++;
|
||||
if (i >= lines.length) return md;
|
||||
i++;
|
||||
let schemaLineIdx = -1;
|
||||
let blockEnd = i;
|
||||
while (i < lines.length && lines[i].startsWith(" ")) {
|
||||
if (lines[i].startsWith(" flagsSchemaVersion:")) schemaLineIdx = i;
|
||||
blockEnd = i + 1;
|
||||
i++;
|
||||
}
|
||||
if (schemaLineIdx >= 0) {
|
||||
if (lines[schemaLineIdx] === ` flagsSchemaVersion: ${version}`) return md; // already current
|
||||
lines[schemaLineIdx] = ` flagsSchemaVersion: ${version}`;
|
||||
} else {
|
||||
lines.splice(blockEnd, 0, ` flagsSchemaVersion: ${version}`);
|
||||
}
|
||||
return lines.join("\n");
|
||||
}
|
||||
|
||||
/** After a successful live push, baseline the note's foundry.contentHash to the current
|
||||
* body hash so a re-run of push-all skips it (idempotent). E1b.2: when `newCcHash` is
|
||||
* provided, also re-baselines foundry.ccHash to the post-push Foundry ccHash so the
|
||||
* next save's divergence guard compares against the pushed state (NOT the pre-push
|
||||
* /get entry — a push changes Foundry, so the pre-push ccHash would false-abort the
|
||||
* next save; the post-push ccHash = ccHash(pushedEntry), no extra /get needed).
|
||||
* Writes via the mirror-aware target (dev: mirror; apply: real vault with .bak).
|
||||
* Returns true if it wrote. */
|
||||
* E1b.8: always stamps foundry.flagsSchemaVersion (the current constant) so every
|
||||
* baselined note carries the schema version. Writes via the mirror-aware target
|
||||
* (dev: mirror; apply: real vault with .bak). Returns true if it wrote. */
|
||||
async function baselineNote(state: State, relPath: string, absPath: string, newCcHash?: string): Promise<boolean> {
|
||||
const md = await readFile(absPath, "utf8");
|
||||
const { body } = splitFrontmatter(md);
|
||||
const updated = baselineFoundryBlock(md, contentHash(body), new Date().toISOString(), newCcHash);
|
||||
const updated = baselineFoundryBlock(md, contentHash(body), new Date().toISOString(), newCcHash, FLAGS_SCHEMA_VERSION);
|
||||
if (updated === md) return false;
|
||||
await writeWithBackup(targetPath(state, "refined", relPath), updated, state);
|
||||
return true;
|
||||
@@ -593,6 +630,14 @@ export class AutoSyncController {
|
||||
// user edit within the TTL has a DIFFERENT mtime → processed normally.
|
||||
private readonly recentlyBaselined = new Map<string, { mtime: number; baselineHash: string; expires: number }>();
|
||||
private readonly baselineSuppressMs = Number(process.env.AUTOSYNC_BASELINE_SUPPRESS_MS ?? 2000);
|
||||
// E1b.8: persistent JSON-lines log (durable record; the in-memory `events`
|
||||
// array is the dashboard's fast poll). Daily + size (10MB) rotation; 14-day
|
||||
// retention at startup. Gated by foundryGuardEnabled.
|
||||
private logStream: WriteStream | null = null;
|
||||
private logDate = "";
|
||||
private logBytes = 0;
|
||||
private readonly logMaxBytes = 10 * 1024 * 1024;
|
||||
private readonly logRetainDays = Math.max(1, Number(process.env.AUTOSYNC_LOG_RETAIN_DAYS ?? 14));
|
||||
// E1b.3: in-memory TOCTOU conflict list (newest first, bounded to 50). A
|
||||
// conflict is recorded when Foundry was edited during the push window (the
|
||||
// post-push /get ccHash ≠ ccHash(pushedEntry)). Cleared for a uuid on its next
|
||||
@@ -607,6 +652,10 @@ export class AutoSyncController {
|
||||
/** E1b.4: the most-recent push record (drives the dashboard "Revert last push"
|
||||
* button). Updated on every successful push. */
|
||||
lastPush: { uuid: string; name: string; backupPath: string; time: string; relPath: string } | null = null;
|
||||
/** E1b.8: count of notes the startup flagsSchemaVersion migration stamped (for
|
||||
* the dashboard banner). Set once at startup. */
|
||||
migrationCount = 0;
|
||||
migrationRan = false;
|
||||
/** E1b.7: uuids mid-retry-backoff. While a uuid is retrying (lock released
|
||||
* during backoff), a concurrent save of the same uuid is dropped (not
|
||||
* duplicated) — checked in `process` before pushWithRetry. */
|
||||
@@ -650,15 +699,83 @@ export class AutoSyncController {
|
||||
conflicts: this.conflicts,
|
||||
// E1b.4: the most-recent push record (drives the "Revert last push" button).
|
||||
lastPush: this.lastPush,
|
||||
// E1b.8: startup flagsSchemaVersion migration result + the current version
|
||||
// (drives the dashboard "Migrated N notes" banner).
|
||||
migrationCount: this.migrationCount,
|
||||
migrationRan: this.migrationRan,
|
||||
schemaVersion: FLAGS_SCHEMA_VERSION,
|
||||
};
|
||||
}
|
||||
|
||||
private log(name: string, status: AutoSyncEvent["status"], message: string): void {
|
||||
this.events.unshift({ time: new Date().toISOString(), name, status, message });
|
||||
const time = new Date().toISOString();
|
||||
this.events.unshift({ time, name, status, message });
|
||||
if (this.events.length > this.maxEvents) this.events.length = this.maxEvents;
|
||||
if (status === "pushed") this.pushed++;
|
||||
else if (status === "error") this.errors++;
|
||||
else this.skipped++;
|
||||
// E1b.8: durable JSON-lines log (flag-gated). Best-effort — never throws.
|
||||
if (this.foundryGuardEnabled) {
|
||||
this.writeLogLine({ time, level: status === "error" ? "error" : "info", name, status, message });
|
||||
}
|
||||
}
|
||||
|
||||
/** E1b.8: append a JSON-line to the daily log file (rotating on date change or
|
||||
* 10MB). Lazy-opens the stream on first write. */
|
||||
private writeLogLine(line: Record<string, unknown>): void {
|
||||
try {
|
||||
this.ensureLogOpen();
|
||||
if (!this.logStream) return;
|
||||
const data = JSON.stringify(line) + "\n";
|
||||
this.logBytes += Buffer.byteLength(data);
|
||||
this.logStream.write(data);
|
||||
if (this.logBytes >= this.logMaxBytes) this.rotateForSize();
|
||||
} catch { /* best-effort — log() must never throw */ }
|
||||
}
|
||||
|
||||
/** Open (or rotate to) the log stream for today's date. */
|
||||
private ensureLogOpen(): void {
|
||||
const today = new Date().toISOString().slice(0, 10);
|
||||
if (this.logStream && this.logDate === today) return;
|
||||
if (this.logStream) { try { this.logStream.end(); } catch { /* close old */ } this.logStream = null; }
|
||||
const dir = join(this.state.cfg.outDir, "logs");
|
||||
try { mkdirSync(dir, { recursive: true }); } catch { /* may already exist */ }
|
||||
const path = join(dir, `sync-${today}.log`);
|
||||
try { this.logBytes = statSync(path).size; } catch { this.logBytes = 0; }
|
||||
this.logStream = createWriteStream(path, { flags: "a" });
|
||||
this.logDate = today;
|
||||
}
|
||||
|
||||
/** Size rotation: rename the current file to sync-<date>.<n>.log and open a
|
||||
* fresh one. */
|
||||
private rotateForSize(): void {
|
||||
if (!this.logStream) return;
|
||||
try { this.logStream.end(); } catch { /* close */ }
|
||||
this.logStream = null;
|
||||
const dir = join(this.state.cfg.outDir, "logs");
|
||||
const base = `sync-${this.logDate}.log`;
|
||||
let n = 1;
|
||||
while (existsSync(join(dir, `sync-${this.logDate}.${n}.log`))) n++;
|
||||
try { void rename(join(dir, base), join(dir, `sync-${this.logDate}.${n}.log`)); } catch { /* best-effort */ }
|
||||
this.logBytes = 0;
|
||||
this.ensureLogOpen(); // opens a fresh empty file for today
|
||||
}
|
||||
|
||||
/** E1b.8: at startup, delete logs/sync-*.log older than `logRetainDays`. */
|
||||
async pruneOldLogs(): Promise<void> {
|
||||
const dir = join(this.state.cfg.outDir, "logs");
|
||||
let files: string[];
|
||||
try { files = await readdir(dir); } catch { return; }
|
||||
const cutoff = Date.now() - this.logRetainDays * 24 * 60 * 60 * 1000;
|
||||
for (const f of files) {
|
||||
if (!f.startsWith("sync-") || !f.endsWith(".log")) continue;
|
||||
try { const st = await stat(join(dir, f)); if (st.mtimeMs < cutoff) await unlink(join(dir, f)); } catch { /* best-effort */ }
|
||||
}
|
||||
}
|
||||
|
||||
/** E1b.8: open today's log stream eagerly (called from startServer). */
|
||||
openLog(): void {
|
||||
if (this.foundryGuardEnabled) this.ensureLogOpen();
|
||||
}
|
||||
|
||||
async setEnabled(on: boolean): Promise<void> {
|
||||
@@ -1118,6 +1235,44 @@ export class AutoSyncController {
|
||||
}, { policy: "queue", maxWaitMs: 5000 });
|
||||
return result ?? { code: 409, body: { error: "lock busy — another operation holds this uuid; try again" } };
|
||||
}
|
||||
|
||||
/** E1b.8: startup migration — stamp foundry.flagsSchemaVersion on matched notes
|
||||
* that lack it (or carry an older value), WITHOUT touching contentHash/ccHash
|
||||
* (so it doesn't falsely trigger a push). Idempotent. In-flight-safe: if the
|
||||
* file's mtime changes between read and write, skip it (the DM is editing).
|
||||
* Runs BEFORE auto-sync is allowed to start. Gated by foundryGuardEnabled.
|
||||
* Returns the count of notes stamped. */
|
||||
async migrateFlagsSchemaVersion(): Promise<number> {
|
||||
if (!this.foundryGuardEnabled) return 0;
|
||||
this.migrationRan = true;
|
||||
const matched = this.state.index?.matched ?? [];
|
||||
let count = 0;
|
||||
for (const row of matched) {
|
||||
if (!row.refinedPath) continue;
|
||||
const name = row.name;
|
||||
try {
|
||||
const abs = await resolveRefined(this.state, relative(this.state.cfg.refinedDir, row.refinedPath) || row.refinedPath);
|
||||
let md: string;
|
||||
const st1 = await stat(abs);
|
||||
try { md = await readFile(abs, "utf8"); } catch { continue; }
|
||||
const fb = readFoundryBlock(splitFrontmatter(md).fm);
|
||||
if (fb?.flagsSchemaVersion === FLAGS_SCHEMA_VERSION) continue; // already current
|
||||
const updated = stampFlagsSchemaVersion(md, FLAGS_SCHEMA_VERSION);
|
||||
if (updated === md) continue;
|
||||
// In-flight check: if the file changed between read and write, skip.
|
||||
const st2 = await stat(abs);
|
||||
if (st1.mtimeMs !== st2.mtimeMs) { this.log(name, "skipped", "in-flight edit — flagsSchemaVersion migration skipped"); continue; }
|
||||
const relPath = relative(this.state.cfg.refinedDir, abs);
|
||||
await writeWithBackup(targetPath(this.state, "refined", relPath), updated, this.state);
|
||||
count++;
|
||||
this.log(name, "skipped", `flagsSchemaVersion migrated ${fb?.flagsSchemaVersion ? "old" : "absent"} -> ${FLAGS_SCHEMA_VERSION}`);
|
||||
} catch (e) {
|
||||
this.log(name, "error", `flagsSchemaVersion migration failed: ${(e as Error).message}`);
|
||||
}
|
||||
}
|
||||
this.migrationCount = count;
|
||||
return count;
|
||||
}
|
||||
}
|
||||
|
||||
export async function startServer(cfg: ServerConfig): Promise<{ server: Server; state: State }> {
|
||||
@@ -1129,6 +1284,16 @@ export async function startServer(cfg: ServerConfig): Promise<{ server: Server;
|
||||
const ov = overlayDirs(state);
|
||||
state.index = await indexAll(db, cfg.ccDir, cfg.refinedDir, ov.refinedOverlay, ov.ccOverlay);
|
||||
|
||||
// E1b.8: open the persistent log + prune old logs, then run the
|
||||
// flagsSchemaVersion startup migration BEFORE auto-sync is allowed to start
|
||||
// (flag-gated). The migration stamps the schema version on notes that lack it,
|
||||
// without touching contentHash/ccHash (no false push).
|
||||
if (state.autosync.foundryGuardEnabled) {
|
||||
await state.autosync.pruneOldLogs();
|
||||
state.autosync.openLog();
|
||||
await state.autosync.migrateFlagsSchemaVersion();
|
||||
}
|
||||
|
||||
const server = createServer(async (req, res) => {
|
||||
try {
|
||||
const url = new URL(req.url ?? "/", "http://127.0.0.1");
|
||||
|
||||
183
tests/e1b8-log-migration.test.ts
Normal file
183
tests/e1b8-log-migration.test.ts
Normal file
@@ -0,0 +1,183 @@
|
||||
// E1b.8 — persistent rotated log + flagsSchemaVersion migration.
|
||||
//
|
||||
// Covers:
|
||||
// 1. log() writes a JSON-line to <outDir>/logs/sync-<date>.log (durable).
|
||||
// 2. a clean push (baselineNote) stamps foundry.flagsSchemaVersion.
|
||||
// 3. the startup migration stamps absent notes (idempotent, no contentHash/
|
||||
// ccHash change); notes already current are left alone.
|
||||
// 4. status() exposes migrationCount + schemaVersion.
|
||||
|
||||
import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
|
||||
import { mkdtemp, writeFile, mkdir, rm, readFile, readdir } from "node:fs/promises";
|
||||
import { existsSync } from "node:fs";
|
||||
import { join } from "node:path";
|
||||
import { tmpdir } from "node:os";
|
||||
|
||||
import { AutoSyncController } from "../src/server.js";
|
||||
import type { State, ServerConfig } from "../src/server.js";
|
||||
import { FLAGS_SCHEMA_VERSION } from "../src/schema-version.js";
|
||||
import { ccHash } from "../src/cchash.js";
|
||||
import { splitFrontmatter, readFoundryBlock } from "../src/frontmatter.js";
|
||||
import type { JournalEntry, CcData } from "../src/types.js";
|
||||
import type { FileRow } from "../src/batch.js";
|
||||
|
||||
const UUID = "JournalEntry.abc1";
|
||||
const REL = "Roland.md";
|
||||
|
||||
function liveEntry(description: string): JournalEntry {
|
||||
return { name: "Roland", _id: "abc1", folder: "Folder.test", flags: { "campaign-codex": { type: "npc", data: { description, notes: "" } } } };
|
||||
}
|
||||
|
||||
let dir: string;
|
||||
let state: State;
|
||||
const realFetch = globalThis.fetch;
|
||||
|
||||
beforeEach(async () => {
|
||||
dir = await mkdtemp(join(tmpdir(), "e1b8-"));
|
||||
await mkdir(join(dir, "refined"), { recursive: true });
|
||||
const cfg: ServerConfig = {
|
||||
journal: "", refinedDir: join(dir, "refined"), ccDir: "", outDir: join(dir, "out"),
|
||||
mode: "apply", port: 0, host: "", relayCfg: { url: "http://relay.test", apiKey: "k", clientId: "c" },
|
||||
};
|
||||
state = { db: {} as State["db"], cfg, index: null, autosync: null as unknown as State["autosync"] } as unknown as State;
|
||||
// Mock relay (behaves like Foundry): /get returns current state, /update applies diff.
|
||||
let currentState: JournalEntry = liveEntry("<p>Original body.</p>");
|
||||
let getCalls = 0;
|
||||
globalThis.fetch = vi.fn(async (url: string, init?: RequestInit) => {
|
||||
const u = String(url); const method = init?.method ?? "GET";
|
||||
const body = init?.body ? JSON.parse(String(init.body)) : undefined;
|
||||
const resp = (o: unknown, ok = true, status = 200) => ({ ok, status, text: async () => (typeof o === "string" ? o : JSON.stringify(o)) });
|
||||
if (method === "GET" && u.includes("/get?")) { getCalls++; return resp({ data: currentState }); }
|
||||
if (method === "GET" && u.includes("/search")) return resp({ results: [] });
|
||||
if (method === "PUT" && u.includes("/update?")) {
|
||||
const diff = body?.data ?? {};
|
||||
currentState = { ...currentState, name: diff.name ?? currentState.name, flags: { ...currentState.flags, "campaign-codex": diff["flags.campaign-codex"] ?? currentState.flags?.["campaign-codex"] } };
|
||||
return resp({ entity: [currentState] });
|
||||
}
|
||||
return resp({ error: "not found" }, false, 404);
|
||||
}) as unknown as typeof fetch;
|
||||
});
|
||||
|
||||
afterEach(async () => { globalThis.fetch = realFetch; await rm(dir, { recursive: true, force: true }); });
|
||||
|
||||
/** A refined note with a STALE contentHash (push proceeds) + a ccHash baseline. */
|
||||
async function writeNote(ccHashBaseline: string, body = "The gunslinger drew his revolver.\n", extraFoundry = ""): Promise<void> {
|
||||
const lines = [
|
||||
"---", "type: npc", "foundry:", ` cc_uuid: ${UUID}`, " cc_type: npc", " folder_path: NPCs",
|
||||
` contentHash: ${"0".repeat(64)}`, ` ccHash: ${ccHashBaseline}`, " syncedAt: 2026-06-22T00:00:00.000Z",
|
||||
];
|
||||
if (extraFoundry) lines.push(extraFoundry);
|
||||
lines.push("---", body, "");
|
||||
await writeFile(join(state.cfg.refinedDir, REL), lines.join("\n"), "utf8");
|
||||
}
|
||||
|
||||
describe("E1b.8a persistent JSON-lines log", () => {
|
||||
it("log() writes a JSON-line to <outDir>/logs/sync-<date>.log", async () => {
|
||||
const controller = new AutoSyncController(state);
|
||||
(controller as any).log("Roland", "pushed", "test push event");
|
||||
// The WriteStream opens + flushes async; poll for the file + content.
|
||||
const today = new Date().toISOString().slice(0, 10);
|
||||
const logPath = join(state.cfg.outDir, "logs", `sync-${today}.log`);
|
||||
let content = "";
|
||||
for (let i = 0; i < 100 && !content; i++) { await new Promise<void>((r) => setTimeout(r, 10)); if (existsSync(logPath)) content = await readFile(logPath, "utf8").catch(() => ""); }
|
||||
expect(content).toContain("test push event");
|
||||
const line = content.trim().split("\n").pop()!;
|
||||
const parsed = JSON.parse(line) as { time: string; level: string; name: string; status: string; message: string };
|
||||
expect(parsed.name).toBe("Roland");
|
||||
expect(parsed.status).toBe("pushed");
|
||||
expect(parsed.message).toBe("test push event");
|
||||
expect(parsed.level).toBe("info");
|
||||
});
|
||||
|
||||
it("an error log line has level 'error'", async () => {
|
||||
const controller = new AutoSyncController(state);
|
||||
(controller as any).log("Roland", "error", "boom");
|
||||
const today = new Date().toISOString().slice(0, 10);
|
||||
const logPath = join(state.cfg.outDir, "logs", `sync-${today}.log`);
|
||||
let content = "";
|
||||
for (let i = 0; i < 100 && !content; i++) { await new Promise<void>((r) => setTimeout(r, 10)); if (existsSync(logPath)) content = await readFile(logPath, "utf8").catch(() => ""); }
|
||||
expect(content).toContain('"level":"error"');
|
||||
expect(content).toContain("boom");
|
||||
});
|
||||
|
||||
it("pruneOldLogs deletes logs older than the retain window", async () => {
|
||||
const logDir = join(state.cfg.outDir, "logs");
|
||||
await mkdir(logDir, { recursive: true });
|
||||
// Write an "old" log file (backdated mtime via utimes is flaky; instead write a
|
||||
// file and rely on mtime being ~now — so test the no-op path: a fresh log is
|
||||
// NOT pruned). Full backdating is awkward; assert the prune runs without error
|
||||
// and a fresh file survives.
|
||||
const fresh = join(logDir, "sync-2026-06-23.log");
|
||||
await writeFile(fresh, "x\n", "utf8");
|
||||
const controller = new AutoSyncController(state);
|
||||
await controller.pruneOldLogs();
|
||||
expect(existsSync(fresh)).toBe(true); // fresh file survives
|
||||
});
|
||||
});
|
||||
|
||||
describe("E1b.8b flagsSchemaVersion baseline + migration", () => {
|
||||
it("a clean push stamps foundry.flagsSchemaVersion on the note", async () => {
|
||||
await writeNote(ccHash(liveEntry("<p>Original body.</p>")));
|
||||
const controller = new AutoSyncController(state);
|
||||
(controller as any).retryBackoffs = [1, 1, 1];
|
||||
await (controller as any).process(REL);
|
||||
const fb = readFoundryBlock(splitFrontmatter(await readFile(join(state.cfg.refinedDir, REL), "utf8")).fm);
|
||||
expect(fb?.flagsSchemaVersion).toBe(FLAGS_SCHEMA_VERSION);
|
||||
});
|
||||
|
||||
function fakeMatchedRow(): FileRow {
|
||||
return {
|
||||
name: "Roland", basename: "Roland", status: "matched" as never,
|
||||
refinedPath: join(state.cfg.refinedDir, REL), ccPath: null, ccId: UUID, ccType: "npc",
|
||||
curatedType: null, entry: null, recommendation: "sync-cc" as never,
|
||||
refinedChanged: false, ccChanged: false, refinedMtime: null, ccMtime: null,
|
||||
storedRefinedHash: null, storedCcHash: null,
|
||||
};
|
||||
}
|
||||
|
||||
it("migration stamps flagsSchemaVersion on a note that lacks it (idempotent, no contentHash/ccHash change)", async () => {
|
||||
// Note WITH contentHash + ccHash but NO flagsSchemaVersion.
|
||||
const baseline = ccHash(liveEntry("<p>Original body.</p>"));
|
||||
await writeNote(baseline);
|
||||
const before = await readFile(join(state.cfg.refinedDir, REL), "utf8");
|
||||
const fbBefore = readFoundryBlock(splitFrontmatter(before).fm);
|
||||
expect(fbBefore?.flagsSchemaVersion).toBeUndefined();
|
||||
|
||||
const controller = new AutoSyncController(state);
|
||||
(state as any).index = { matched: [fakeMatchedRow()], ccOnly: [], refinedOnly: [], counts: { matched: 1, ccOnly: 0, refinedOnly: 0, unlinked: 0 } };
|
||||
const count = await controller.migrateFlagsSchemaVersion();
|
||||
expect(count).toBe(1);
|
||||
|
||||
const after = await readFile(join(state.cfg.refinedDir, REL), "utf8");
|
||||
const fbAfter = readFoundryBlock(splitFrontmatter(after).fm);
|
||||
expect(fbAfter?.flagsSchemaVersion).toBe(FLAGS_SCHEMA_VERSION);
|
||||
// contentHash + ccHash UNTOUCHED (no false push trigger).
|
||||
expect(fbAfter?.contentHash).toBe(fbBefore?.contentHash);
|
||||
expect(fbAfter?.ccHash).toBe(baseline);
|
||||
|
||||
// Idempotent: a second migration run stamps nothing.
|
||||
const count2 = await controller.migrateFlagsSchemaVersion();
|
||||
expect(count2).toBe(0);
|
||||
});
|
||||
|
||||
it("migration leaves a note that already has the current version alone", async () => {
|
||||
const baseline = ccHash(liveEntry("<p>Original body.</p>"));
|
||||
await writeNote(baseline, "The gunslinger drew his revolver.\n", ` flagsSchemaVersion: ${FLAGS_SCHEMA_VERSION}`);
|
||||
const controller = new AutoSyncController(state);
|
||||
(state as any).index = { matched: [fakeMatchedRow()], ccOnly: [], refinedOnly: [], counts: { matched: 1, ccOnly: 0, refinedOnly: 0, unlinked: 0 } };
|
||||
const count = await controller.migrateFlagsSchemaVersion();
|
||||
expect(count).toBe(0); // already current
|
||||
});
|
||||
|
||||
it("status() exposes migrationCount + schemaVersion", async () => {
|
||||
const baseline = ccHash(liveEntry("<p>Original body.</p>"));
|
||||
await writeNote(baseline);
|
||||
const controller = new AutoSyncController(state);
|
||||
(state as any).index = { matched: [fakeMatchedRow()], ccOnly: [], refinedOnly: [], counts: { matched: 1, ccOnly: 0, refinedOnly: 0, unlinked: 0 } };
|
||||
await controller.migrateFlagsSchemaVersion();
|
||||
const s = controller.status();
|
||||
expect(s.migrationRan).toBe(true);
|
||||
expect(s.migrationCount).toBe(1);
|
||||
expect(s.schemaVersion).toBe(FLAGS_SCHEMA_VERSION);
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user