fix(facts,cycle,doctor): three backlog fixes — fence stub-dup, probe self-mute, wedged-queue misdiagnosis

- #3069 (facts): writeFactsToFence resolved the entity file by slug only,
  so a page whose on-disk basename differs from its slug (vault files like
  '10-people/First Last.md' → slug '10-people/first-last') missed existsSync
  and stub-created a duplicate page whose empty fence restarted row_num at 1,
  colliding with the real page's DB rows on idx_facts_fence_key. Now resolves
  the real file via the page row (source_path, then import_filename) before
  stub-creating, and routes to the legacy DB-only path when a page row exists
  but its backing file can't be located (stub-creating there would both
  collide and let a later sync import the stub over the real content).

- #3064 (cycle): the nightly quality probe's 24h gate counted its own
  'rate_limited' skip audit rows, and autopilot ticks every ~5 min — each
  skip re-armed the window, so the probe ran exactly once and then self-muted
  forever (~288 skip rows/day, which also perma-warned doctor's
  nightly_quality_probe_health). The gate now filters skip rows (defends
  against historical rows on pre-fix brains) and the skip no longer logs an
  audit event.

- #3063 (doctor): computeWedgedQueueCheck unconditionally blamed a wedged DB
  pool ('worker alive but not claiming work ... rebuilds a fresh DB pool')
  without observing worker liveness. It now checks the supervisor's singleton
  DB lock per wedged queue: no live holder → 'no waiting jobs and no worker
  running' with the `gbrain jobs supervisor start` remedy; live holder →
  the existing wedged-pool message. Lock-table read errors keep the
  conservative wedged-pool message.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Garry Tan
2026-07-23 11:05:39 -07:00
co-authored by Claude Fable 5
parent 50406fc212
commit 0431dfd67f
6 changed files with 231 additions and 27 deletions
+46 -8
View File
@@ -1623,7 +1623,7 @@ export async function computeWedgedQueueCheck(engine: BrainEngine): Promise<Chec
FROM minion_jobs
GROUP BY queue`,
);
const wedged: string[] = [];
const wedged: Array<{ queue: string; label: string }> = [];
for (const r of rows) {
const activeHealthy = Number(r.active_healthy ?? 0);
const waiting = Number(r.waiting ?? 0);
@@ -1631,21 +1631,59 @@ export async function computeWedgedQueueCheck(engine: BrainEngine): Promise<Chec
// Conservative: only flag stale-after-progress (non-null mins past
// threshold). The null-completions case is the supervisor's job.
if (activeHealthy === 0 && waiting > 0 && mins !== null && mins > thresholdMin) {
wedged.push(`'${r.queue}' (${waiting} waiting, 0 active, ${Math.round(mins)}m since last completion)`);
wedged.push({
queue: r.queue,
label: `'${r.queue}' (${waiting} waiting, 0 active, ${Math.round(mins)}m since last completion)`,
});
}
}
if (wedged.length === 0) {
return { name: 'wedged_queue', status: 'ok', message: 'No wedged queues' };
}
return {
name: 'wedged_queue',
status: 'fail',
message:
`Wedged queue(s) — worker alive but not claiming work: ${wedged.join('; ')}. ` +
// #3063: split the diagnosis on worker liveness. The wedged-pool message
// ("worker alive but not claiming work → restart to rebuild the DB pool")
// only applies when a supervisor actually holds a live singleton lock.
// With no live holder the worker is simply not running — telling the
// operator to blame the DB pool sends them down the wrong path.
const alive: string[] = [];
const noWorker: string[] = [];
for (const w of wedged) {
let hasLiveWorker = false;
try {
const { supervisorLockId } = await import('../core/minions/supervisor.ts');
const lockRows = await engine.executeRaw<{ live: boolean }>(
`SELECT (ttl_expires_at > now()) AS live FROM gbrain_cycle_locks WHERE id = $1`,
[supervisorLockId(w.queue)],
);
hasLiveWorker = lockRows.length > 0 && lockRows[0].live === true;
} catch {
// Lock table unreadable → can't prove absence; keep the
// conservative wedged-pool message.
hasLiveWorker = true;
}
(hasLiveWorker ? alive : noWorker).push(w.label);
}
const parts: string[] = [];
if (noWorker.length > 0) {
parts.push(
`Queue(s) with waiting jobs and no worker running: ${noWorker.join('; ')}. ` +
`Start the worker: \`gbrain jobs supervisor start\` ` +
`(or restart the autopilot unit if installed).`,
);
}
if (alive.length > 0) {
parts.push(
`Wedged queue(s) — worker alive but not claiming work: ${alive.join('; ')}. ` +
`Restart the worker so it rebuilds a fresh DB pool: ` +
`\`gbrain jobs supervisor stop && gbrain jobs supervisor start\`, ` +
`then \`gbrain jobs retry <id>\` on any dead-lettered jobs.`,
details: { wedged_queues: wedged.length, threshold_minutes: thresholdMin },
);
}
return {
name: 'wedged_queue',
status: 'fail',
message: parts.join(' '),
details: { wedged_queues: wedged.length, no_worker_queues: noWorker.length, threshold_minutes: thresholdMin },
};
} catch (e) {
// Pre-migration brains / transient errors: advisory check stays ok.
+11 -12
View File
@@ -101,21 +101,20 @@ export async function runNightlyQualityProbe(deps: NightlyProbeDeps): Promise<Ni
return { outcome: 'disabled', exit_code: 0, detail: 'feature flag off' };
}
// 24h rate limit — skip + audit "rate_limited".
// 24h rate limit — skip quietly (no audit row).
// #3064: gate only on events from ATTEMPTED runs. The skip path used to log
// its own 'rate_limited' audit row, and autopilot ticks every ~5 min — each
// skip re-armed the 24h window, so the probe ran exactly once and then
// self-muted forever. Filter defends against historical skip rows already
// sitting in the audit files of pre-fix brains.
const now = deps.now();
const recent = readRecentQualityProbeEvents(2, now); // 2-day window is enough for 24h check
const decision = shouldRunNightly(now, recent);
const decision = shouldRunNightly(now, recent.filter((e) => e.outcome !== 'rate_limited'));
if (!decision.run) {
logQualityProbeEvent({
outcome: 'rate_limited',
exit_code: 0,
pass_count: 0,
fail_count: 0,
inconclusive_count: 0,
error_count: 0,
est_cost_usd: 0,
detail: 'already ran within 24h window',
});
// #3064: do NOT log an audit row here. Autopilot ticks every ~5 min, so
// the skip fires ~288x/day between real runs — logging each one spammed
// the audit JSONL and permanently tripped doctor's
// nightly_quality_probe_health warn (rate_limited counts as non-PASS).
return { outcome: 'rate_limited', exit_code: 0, detail: 'already ran within 24h' };
}
+56 -4
View File
@@ -34,7 +34,7 @@
*/
import { existsSync, mkdirSync, readFileSync, writeFileSync, renameSync, appendFileSync } from 'node:fs';
import { dirname } from 'node:path';
import { dirname, join } from 'node:path';
import type { BrainEngine, NewFact, FactVisibility } from '../engine.ts';
import { resolvePageFilePath } from '../markdown.ts';
@@ -172,17 +172,68 @@ export async function writeFactsToFence(
// the put_page write-through and dream-cycle reverse-render compute. The
// bare join wrote main-source fences to the repo ROOT (the default source's
// tree), polluting ~/brain with stray root-level fence files.
const filePath = resolvePageFilePath(target.localPath, target.slug, target.sourceId);
const tmpPath = `${filePath}.tmp`;
let filePath = resolvePageFilePath(target.localPath, target.slug, target.sourceId);
return withPageLock(
target.slug,
async () => {
// 1. Read existing body or stub-create.
let body: string;
let body: string | null = null;
if (existsSync(filePath)) {
body = readFileSync(filePath, 'utf-8');
} else {
// #3069: the slug-derived path missed, but the page may still exist
// on disk under a different basename — vault files like
// `10-people/First Last.md` import with slug `10-people/first-last`,
// so `<root>/<slug>.md` doesn't exist even though the page does.
// Stub-creating next to the real file (a) duplicates the page and
// (b) restarts fence row_num at 1 on the empty stub, colliding with
// the real page's existing DB rows on idx_facts_fence_key. Resolve
// via the page row (sync stamps source_path + import_filename)
// before concluding the page doesn't exist.
let pageRow: { source_path: string | null; import_filename: string | null } | null = null;
try {
const rows = await engine.executeRaw<{ source_path: string | null; import_filename: string | null }>(
`SELECT source_path, import_filename FROM pages WHERE slug = $1 AND source_id = $2 AND deleted_at IS NULL LIMIT 1`,
[target.slug, target.sourceId],
);
pageRow = rows[0] ?? null;
} catch {
// Lookup failed (pre-migration schema, transient) — fall through
// to the pre-#3069 stub path rather than dropping the facts.
}
if (pageRow !== null) {
const candidates: string[] = [];
if (pageRow.source_path) {
candidates.push(join(target.localPath!, pageRow.source_path));
}
if (pageRow.import_filename) {
const name = pageRow.import_filename.endsWith('.md')
? pageRow.import_filename
: `${pageRow.import_filename}.md`;
candidates.push(join(dirname(filePath), name));
}
const hit = candidates.find((c) => existsSync(c));
if (hit !== undefined) {
filePath = hit;
body = readFileSync(filePath, 'utf-8');
} else {
// A page row exists but its backing file can't be located.
// Refuse to stub-create (the empty stub's fence would restart
// row_num at 1 → unique violation against the row's existing
// facts, and a later sync would import the stub OVER the real
// page content). Route to the legacy DB-only path instead so
// the facts aren't dropped.
// eslint-disable-next-line no-console
console.warn(
`[facts] page row exists for slug=${target.slug} (source=${target.sourceId}) but its backing file was not found on disk — refusing to stub-create a duplicate page; routing to legacy DB-only path.`,
);
return { inserted: 0, ids: [], stubGuardBlocked: true };
}
}
}
if (body === null) {
// No page row for this slug — genuinely new entity page.
// Stub-creation guard. Phantom entity pages at the brain root were
// being spawned when resolveEntitySlug fell through to a bare
// slugify because pg_trgm scored too low on short bare names. The
@@ -238,6 +289,7 @@ export async function writeFactsToFence(
}
// 3. Atomic write: .tmp first, then parse-validate, then rename.
const tmpPath = `${filePath}.tmp`;
writeFileSync(tmpPath, body, 'utf-8');
// 4. Parse-before-rename: re-read the .tmp content and verify the
+28
View File
@@ -97,6 +97,34 @@ describe('issue #1801 fix #3 — computeWedgedQueueCheck', () => {
expect(check.message).not.toContain("'q-healthy'");
});
it('#3063: wedged queue with NO live supervisor → "no worker running", not the DB-pool message', async () => {
await seed('default', 'cycle', 'waiting');
await seed('default', 'cycle', 'completed', { updatedAtSql: "now() - interval '20 min'" });
// No gbrain_cycle_locks row for gbrain-supervisor:default.
const check = await computeWedgedQueueCheck(pgLike);
expect(check.status).toBe('fail');
expect(check.message).toContain('no worker running');
expect(check.message).toContain('gbrain jobs supervisor start');
expect(check.message).not.toContain('rebuilds a fresh DB pool');
});
it('#3063: wedged queue WITH a live supervisor lock → keeps the wedged-pool message', async () => {
await seed('default', 'cycle', 'waiting');
await seed('default', 'cycle', 'completed', { updatedAtSql: "now() - interval '20 min'" });
await base.executeRaw(
`INSERT INTO gbrain_cycle_locks (id, holder_pid, holder_host, acquired_at, ttl_expires_at, last_refreshed_at)
VALUES ('gbrain-supervisor:default', 12345, 'test-host', now(), now() + interval '5 min', now())`,
);
try {
const check = await computeWedgedQueueCheck(pgLike);
expect(check.status).toBe('fail');
expect(check.message).toContain('worker alive but not claiming work');
expect(check.message).toContain('rebuilds a fresh DB pool');
} finally {
await base.executeRaw(`DELETE FROM gbrain_cycle_locks WHERE id = 'gbrain-supervisor:default'`);
}
});
it('returns ok on PGLite (no multi-process worker surface)', async () => {
const check = await computeWedgedQueueCheck(base as unknown as BrainEngine);
expect(check.status).toBe('ok');
+68
View File
@@ -273,6 +273,74 @@ describe('writeFactsToFence — stub guard (v0.34.5)', () => {
});
});
describe('writeFactsToFence — basename ≠ slug (#3069)', () => {
test('resolves the real file via the page row instead of stub-creating a duplicate', async () => {
// Vault file whose basename differs from its slug — the way sync imports
// `10-people/Joey Example.md` as slug `10-people/joey-example`.
mkdirSync(join(brainDir, '10-people'), { recursive: true });
const realPath = join(brainDir, '10-people/Joey Example.md');
writeFileSync(
realPath,
'---\ntype: person\ntitle: Joey Example\nslug: 10-people/joey-example\n---\n\n# Joey Example\n\n## Facts\n\n<!--- gbrain:facts:begin -->\n| # | claim | kind | confidence | visibility | notability | valid_from | valid_until | source | context |\n|---|-------|------|------------|------------|------------|------------|-------------|--------|---------|\n| 1 | Existing claim | fact | 1.0 | world | medium | 2024-01-01 | | import | |\n<!--- gbrain:facts:end -->\n',
'utf-8',
);
await engine.putPage('10-people/joey-example', {
type: 'person',
title: 'Joey Example',
compiled_truth: '# Joey Example',
timeline: '',
frontmatter: {},
content_hash: 'x',
source_path: '10-people/Joey Example.md',
import_filename: 'Joey Example',
});
const result = await writeFactsToFence(
engine,
{ sourceId: 'default', localPath: brainDir, slug: '10-people/joey-example' },
[baseInput({ fact: 'New claim after rename' })],
);
expect(result.inserted).toBe(1);
expect(result.stubGuardBlocked).toBeUndefined();
// No duplicate stub next to the real page.
expect(existsSync(join(brainDir, '10-people/joey-example.md'))).toBe(false);
// The fact landed on the REAL file, continuing the fence's row_num
// sequence (a stub would have restarted at 1 → idx_facts_fence_key
// collision against the real page's DB rows).
const body = readFileSync(realPath, 'utf-8');
expect(body).toContain('New claim after rename');
// eslint-disable-next-line @typescript-eslint/no-explicit-any
const rows = await (engine as any).db.query(
`SELECT row_num FROM facts WHERE source_markdown_slug = '10-people/joey-example'`,
);
expect(rows.rows[0].row_num).toBe(2);
});
test('page row exists but backing file is gone → stubGuardBlocked, no stub created', async () => {
await engine.putPage('10-people/ghost-page', {
type: 'person',
title: 'Ghost',
compiled_truth: '',
timeline: '',
frontmatter: {},
content_hash: 'y',
source_path: '10-people/Ghost Page.md', // never written to disk
import_filename: 'Ghost Page',
});
const result = await writeFactsToFence(
engine,
{ sourceId: 'default', localPath: brainDir, slug: '10-people/ghost-page' },
[baseInput()],
);
expect(result.inserted).toBe(0);
expect(result.stubGuardBlocked).toBe(true);
expect(existsSync(join(brainDir, '10-people/ghost-page.md'))).toBe(false);
});
});
describe('lookupSourceLocalPath', () => {
test('returns the configured local_path for an existing source', async () => {
const got = await lookupSourceLocalPath(engine, 'default');
+22 -3
View File
@@ -132,7 +132,7 @@ describe('runNightlyQualityProbe (DI stub harness)', () => {
});
});
test('enabled + recent run within 24h → outcome: rate_limited', async () => {
test('enabled + recent run within 24h → outcome: rate_limited (no audit row for the skip)', async () => {
// Pre-seed a recent audit event by running the probe once first.
await withEnv({ GBRAIN_AUDIT_DIR: auditTmp }, async () => {
// First run succeeds.
@@ -140,9 +140,28 @@ describe('runNightlyQualityProbe (DI stub harness)', () => {
// Second run, same hour → rate_limited.
const r2 = await runNightlyQualityProbe(makeDeps());
expect(r2.outcome).toBe('rate_limited');
// #3064: the skip does NOT log an audit row — autopilot ticks every
// ~5 min, so skip rows would spam the JSONL and (pre-fix) re-arm the
// 24h window on every tick, muting the probe forever after one run.
const events = await readEvents();
expect(events.length).toBe(2);
expect(events[1].outcome).toBe('rate_limited');
expect(events.length).toBe(1);
expect(events[0].outcome).toBe('pass');
});
});
test('#3064 regression: historical rate_limited skip rows do NOT re-arm the 24h window', async () => {
await withEnv({ GBRAIN_AUDIT_DIR: auditTmp }, async () => {
const { logQualityProbeEvent } = await import('../src/core/audit-quality-probe.ts');
const now = new Date();
const zero = { exit_code: 0, pass_count: 0, fail_count: 0, inconclusive_count: 0, error_count: 0, est_cost_usd: 0 };
// Real run 25h ago (outside the window)...
logQualityProbeEvent({ outcome: 'pass', ts: new Date(now.getTime() - 25 * 3600_000).toISOString(), ...zero });
// ...plus skip rows a pre-fix brain logged on every autopilot tick.
logQualityProbeEvent({ outcome: 'rate_limited', ts: new Date(now.getTime() - 10 * 60_000).toISOString(), ...zero });
logQualityProbeEvent({ outcome: 'rate_limited', ts: new Date(now.getTime() - 5 * 60_000).toISOString(), ...zero });
const r = await runNightlyQualityProbe(makeDeps({ now: () => now }));
expect(r.outcome).toBe('pass'); // pre-fix: 'rate_limited' forever
});
});