Skip to content

Commit 0c5d035

Browse files
claude[bot]claude
andauthored
fix(metadata): a failing history cleanup run is no longer silent, at both of start()’s triggers (#16177)
* fix(metadata): a failing history cleanup run is no longer silent at either start() trigger Every inner catch on `runCleanup()`'s delete path is a bare `catch {`, so the error object is discarded; the only `console.error` in the method sits in its OUTER catch, which those inner catches prevent execution from reaching; and `start()` invoked the run as `void this.runCleanup()` at BOTH call sites — the immediate run and every interval tick — discarding the `{ deleted, errors }` the run returns. A driver whose deletes failed on every scheduled run produced zero output and no reachable error count. Read the envelope rather than replace it. `runCleanup()`'s contract, its inner catches and its counting are untouched: handing a failure to the CALLER is the third answer AGENTS.md "Degradation log levels" allows a durability seam, and that section names a log per failed write as the mirror-image failure. What was missing was a reader, and `start()` is where the chain ends — it returns void and an interval tick has no caller. Both call sites now go through one private pass that reads the counts and prints a single `error` line, naming the consequence and the fix, when a run lost deletes. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARYe3yQTQCUFm5qPYNgKaJ * refactor(metadata): lift the cleanup reporter out of the class so the published declaration does not move `private` members are emitted into the published `dist/*.d.ts` and join the class's nominal identity, so a private method would have made an observability repair change `@objectstack/metadata`'s declaration surface. As a module-level function — the idiom this file already uses for `executionPinnedTypes()` — it changes none of it. Behaviour, call sites and the pin are unchanged. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01ARYe3yQTQCUFm5qPYNgKaJ --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent 1cf7392 commit 0c5d035

3 files changed

Lines changed: 270 additions & 3 deletions

File tree

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,9 @@
1+
---
2+
'@objectstack/metadata': patch
3+
---
4+
5+
fix(metadata): a `HistoryCleanupManager` run that loses deletes now says so, at both of `start()`'s triggers
6+
7+
A failing history cleanup was completely silent. Three things composed: every inner `catch` on the delete path is a bare `catch {`, so the error object is discarded; the only `console.error` in `runCleanup()` sits in its OUTER catch, which those inner catches prevent execution from reaching; and `start()` invoked the run as `void this.runCleanup()`, throwing away the `{ deleted, errors }` the run returns — at BOTH call sites, the immediate run and every interval tick. A driver whose deletes failed on every scheduled run therefore produced zero output and no reachable error count, while the history table grew past its retention policy with nothing to find.
8+
9+
The repair reads the envelope instead of replacing it. `runCleanup()`'s contract, its inner catches and its counting are unchanged: reporting a failure to the CALLER is the third answer AGENTS.md → "Degradation log levels" allows a durability seam, and that same section names a log per failed write as the mirror-image failure. What was missing was a reader — `start()` is where the chain ends, since it returns `void` and an interval tick has no caller at all. Both call sites now go through one shared pass that reads the returned counts and, when a run lost deletes, prints one `error` line naming the consequence (rows past the retention policy are still in the table, nothing retries them, and the system keeps reporting healthy) and where to look. A run that loses nothing stays quiet, and a direct caller of `runCleanup()` sees exactly the same `{ deleted, errors }` as before.
Lines changed: 195 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,195 @@
1+
// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license.
2+
3+
/**
4+
* #16061 — a cleanup run that loses deletes must SAY SO, at both triggers.
5+
*
6+
* ## The closed loop this file pins open
7+
*
8+
* Three things composed to make a failing cleanup completely silent:
9+
*
10+
* 1. every inner `catch` on the delete path is a bare `catch {` — unbound,
11+
* so the error object is gone;
12+
* 2. the only `console.error` in `runCleanup()` sits in its OUTER catch,
13+
* which the inner catches prevent execution from reaching;
14+
* 3. `start()` invoked the run as `void this.runCleanup()`, discarding the
15+
* `{ deleted, errors }` the run returns — at BOTH call sites.
16+
*
17+
* ⇒ A driver whose deletes fail on every scheduled run produced zero output
18+
* and no reachable error count. The history table grew past its retention
19+
* policy with nothing to find.
20+
*
21+
* ## What is asserted, and what is deliberately NOT
22+
*
23+
* The subject is the SIGNAL, not the cleanup. Adding a report here is not an
24+
* enhancement — it turns an error path that already exists from unobservable
25+
* into observable — so every case below asserts that a failing run produces
26+
* something an operator can read, and none of them asserts that any row was
27+
* deleted.
28+
*
29+
* ⛔ Not pinned: the wording of the report, beyond the two facts AGENTS.md →
30+
* "Degradation log levels" says such a line owes — the consequence and the
31+
* fix — plus the failure count, which is the only thing `runCleanup()`
32+
* carries out of the swallowing catches. Pinning the prose would make every
33+
* later clarification a test edit.
34+
*
35+
* ⛔ Not changed, and asserted unchanged: `runCleanup()`'s own contract. Its
36+
* inner catches stay silent on purpose — the same AGENTS.md section names a
37+
* log per failed write as the mirror-image failure and calls a failure handed
38+
* to the CALLER the third legal answer. The defect was never that the seams
39+
* report through the envelope; it was that nobody read the envelope.
40+
*
41+
* ## Why the two triggers are separate cases
42+
*
43+
* `start()` runs the pass twice over: once immediately, and once per interval
44+
* tick. Both were `void this.runCleanup()`. Repairing only the immediate one
45+
* leaves every SCHEDULED run silent — which is the defect, for the trigger
46+
* that runs forever rather than the one that runs once. A single case that
47+
* only counted reports could pass on a half-fix, so the immediate run and a
48+
* tick are asserted separately.
49+
*/
50+
51+
import { describe, it, expect, vi, afterEach } from 'vitest';
52+
import type { IDataDriver } from '@objectstack/spec/contracts';
53+
import type { MetadataHistoryRetentionPolicy } from '@objectstack/spec/system';
54+
import type { DatabaseLoader } from '../loaders/database-loader.js';
55+
import { HistoryCleanupManager } from './history-cleanup.js';
56+
57+
const TABLE = 'sys_metadata_history';
58+
const HOUR_MS = 60 * 60 * 1000;
59+
60+
/** Every delete the age branch attempts, and whether the driver refuses it. */
61+
interface DriverLog {
62+
deleteManyCalls: number;
63+
}
64+
65+
/**
66+
* A manager over a driver whose bulk delete either refuses or succeeds.
67+
*
68+
* `HistoryCleanupManager` reads `driver`, `historyTableName` and
69+
* `organizationId` off the loader by property, so a plain object is enough
70+
* (the same stub shape `history-cleanup-dst.test.ts` uses).
71+
*/
72+
function managerFor(
73+
mode: 'refuses' | 'succeeds',
74+
log: DriverLog,
75+
policy: MetadataHistoryRetentionPolicy,
76+
): HistoryCleanupManager {
77+
const driver = {
78+
deleteMany(table: string, _filter: Record<string, unknown>): number {
79+
expect(table).toBe(TABLE);
80+
log.deleteManyCalls++;
81+
if (mode === 'refuses') {
82+
throw new Error('driver refused the delete');
83+
}
84+
return 0;
85+
},
86+
find(): Record<string, unknown>[] {
87+
throw new Error('the maxVersions branch must not run in these cases');
88+
},
89+
} as unknown as IDataDriver;
90+
91+
const loader = {
92+
driver,
93+
historyTableName: TABLE,
94+
organizationId: undefined,
95+
} as unknown as DatabaseLoader;
96+
97+
return new HistoryCleanupManager(policy, loader);
98+
}
99+
100+
/** Join one `console.error` call's arguments into the text an operator reads. */
101+
function textOf(call: unknown[]): string {
102+
return call.map((a) => (typeof a === 'string' ? a : String(a))).join(' ');
103+
}
104+
105+
afterEach(() => {
106+
vi.useRealTimers();
107+
vi.restoreAllMocks();
108+
});
109+
110+
describe('#16061 — a failing history cleanup is not silent', () => {
111+
it('reports the IMMEDIATE run started by start()', async () => {
112+
const log: DriverLog = { deleteManyCalls: 0 };
113+
const errors = vi.spyOn(console, 'error').mockImplementation(() => {});
114+
vi.useFakeTimers();
115+
116+
const manager = managerFor('refuses', log, {
117+
autoCleanup: true,
118+
maxAgeDays: 30,
119+
cleanupIntervalHours: 1,
120+
});
121+
122+
manager.start();
123+
// Let the immediate run settle without advancing to the first tick.
124+
await vi.advanceTimersByTimeAsync(0);
125+
manager.stop();
126+
127+
// The run really ran and really lost a delete — without this the case
128+
// could pass over a driver that was never asked.
129+
expect(log.deleteManyCalls).toBe(1);
130+
131+
expect(errors).toHaveBeenCalledTimes(1);
132+
const text = textOf(errors.mock.calls[0]);
133+
expect(text).toMatch(/history cleanup/i);
134+
// The count is the only thing carried out of the swallowing catches.
135+
expect(text).toContain('1');
136+
// The two things AGENTS.md says such a line owes.
137+
expect(text).toMatch(/still in the table|grows past the retention policy/i);
138+
expect(text).toMatch(/fix:/i);
139+
});
140+
141+
it('reports EVERY SCHEDULED run, not only the first', async () => {
142+
const log: DriverLog = { deleteManyCalls: 0 };
143+
const errors = vi.spyOn(console, 'error').mockImplementation(() => {});
144+
vi.useFakeTimers();
145+
146+
const manager = managerFor('refuses', log, {
147+
autoCleanup: true,
148+
maxAgeDays: 30,
149+
cleanupIntervalHours: 1,
150+
});
151+
152+
manager.start();
153+
await vi.advanceTimersByTimeAsync(0);
154+
expect(errors).toHaveBeenCalledTimes(1);
155+
156+
// One interval tick. This is the SECOND call site; a fix applied only to
157+
// the immediate run leaves this one silent and this expectation red.
158+
await vi.advanceTimersByTimeAsync(HOUR_MS);
159+
manager.stop();
160+
161+
expect(log.deleteManyCalls).toBe(2);
162+
expect(errors).toHaveBeenCalledTimes(2);
163+
expect(textOf(errors.mock.calls[1])).toMatch(/history cleanup/i);
164+
});
165+
166+
it('CONTROL — a run that loses nothing says nothing', async () => {
167+
const log: DriverLog = { deleteManyCalls: 0 };
168+
const errors = vi.spyOn(console, 'error').mockImplementation(() => {});
169+
vi.useFakeTimers();
170+
171+
const manager = managerFor('succeeds', log, {
172+
autoCleanup: true,
173+
maxAgeDays: 30,
174+
cleanupIntervalHours: 1,
175+
});
176+
177+
manager.start();
178+
await vi.advanceTimersByTimeAsync(0);
179+
await vi.advanceTimersByTimeAsync(HOUR_MS);
180+
manager.stop();
181+
182+
// Same code path, same two triggers, driver simply does not refuse.
183+
expect(log.deleteManyCalls).toBe(2);
184+
expect(errors).not.toHaveBeenCalled();
185+
});
186+
187+
it('leaves runCleanup()\'s envelope exactly as it was', async () => {
188+
const log: DriverLog = { deleteManyCalls: 0 };
189+
const manager = managerFor('refuses', log, { maxAgeDays: 30 });
190+
191+
// A DIRECT caller still gets the counts, unchanged: the repair reads the
192+
// envelope, it does not replace it.
193+
await expect(manager.runCleanup()).resolves.toEqual({ deleted: 0, errors: 1 });
194+
});
195+
});

packages/metadata/src/utils/history-cleanup.ts

Lines changed: 66 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -51,12 +51,13 @@ export class HistoryCleanupManager {
5151

5252
const intervalMs = (this.policy.cleanupIntervalHours ?? 24) * 60 * 60 * 1000;
5353

54-
// Run cleanup immediately on start
55-
void this.runCleanup();
54+
// Run cleanup immediately on start. Both call sites go through
55+
// `runCleanupAndReport()`, never `runCleanup()` — see its docblock.
56+
void runCleanupAndReport(this);
5657

5758
// Schedule periodic cleanup
5859
this.cleanupTimer = setInterval(() => {
59-
void this.runCleanup();
60+
void runCleanupAndReport(this);
6061
}, intervalMs);
6162
}
6263

@@ -315,3 +316,65 @@ export class HistoryCleanupManager {
315316
};
316317
}
317318
}
319+
320+
/**
321+
* Run one cleanup pass for {@link HistoryCleanupManager.start} and report a
322+
* run that lost deletes.
323+
*
324+
* `runCleanup()` reports its failures to the CALLER, in the `errors` field of
325+
* the `{ deleted, errors }` envelope it returns. That is the third answer
326+
* AGENTS.md → "Degradation log levels" allows a durability seam, and it is why
327+
* that method's inner `catch` clauses are deliberately silent: the same
328+
* section names a log per failed write as the mirror-image failure, and asks
329+
* for one report, at the first degradation, naming the consequence and the
330+
* fix.
331+
*
332+
* A failure handed to the caller is only reported while somebody READS it, and
333+
* `start()` is where that chain ends — it returns `void`, and the interval tick
334+
* has no caller at all. Both call sites used to spell the run
335+
* `void this.runCleanup()`, so a driver whose deletes failed produced no output
336+
* and no reachable count: the history table grew past its retention policy and
337+
* nothing said so.
338+
*
339+
* So the envelope is read HERE, once per run. Restoring
340+
* `void this.runCleanup()` at EITHER call site re-opens the defect for that
341+
* trigger alone — a startup-only report leaves every scheduled run silent —
342+
* which is why the pin asserts the immediate run and an interval tick
343+
* separately.
344+
*
345+
* Module-level, and NOT a private method, on purpose: TypeScript emits
346+
* `private` members into the published `dist/*.d.ts` and they join the class's
347+
* nominal identity, so a private method would have made an observability
348+
* repair move the published declaration. As a free function it changes none of
349+
* it — measured, all 10 published declaration files byte-identical.
350+
*
351+
* Resolves rather than rejects on every path, so `void` at the call sites
352+
* cannot turn a cleanup failure into an unhandled rejection.
353+
*/
354+
async function runCleanupAndReport(manager: HistoryCleanupManager): Promise<void> {
355+
let outcome: { deleted: number; errors: number };
356+
357+
try {
358+
outcome = await manager.runCleanup();
359+
} catch (error) {
360+
console.error(
361+
'History cleanup: the run did not complete, so no history row past the retention '
362+
+ 'policy was deleted and the table keeps growing while the system reports healthy. '
363+
+ 'Fix: the cause below comes from the configured data driver, not from the retention '
364+
+ 'policy; call `runCleanup()` directly to reproduce it. Cause:',
365+
error,
366+
);
367+
return;
368+
}
369+
370+
if (outcome.errors > 0) {
371+
console.error(
372+
`History cleanup: ${outcome.errors} delete operation(s) failed and `
373+
+ `${outcome.deleted} row(s) were deleted. The history rows those deletes were meant `
374+
+ 'to remove are still in the table, nothing retries them, and the table grows past '
375+
+ 'the retention policy while the system keeps reporting healthy. Fix: check the data '
376+
+ 'driver delete path for the metadata history table. The per-failure causes are not '
377+
+ 'carried out of `runCleanup()`, so reproduce them against the driver directly.',
378+
);
379+
}
380+
}

0 commit comments

Comments
 (0)