fix: stop full database rewrites on every plugin db call

This commit is contained in:
LukeGus committed 2026-10-05 20:10:09 -05:00
1 parent 040fbfe315
commit 853615af09
11 files changed
+313 -26

No files matched your search

@@ -142,6 +142,42 @@ describe("AuditLogRepository", () => {
).toEqual(["user-2"]);
});
it("clears only background routine plugin entries", async () => {
let writeCount = 0;
const repo = await createRepository(() => {
writeCount += 1;
});
const entry = (userId: string | null, action: string) =>
repo.create({
userId,
username: "plugin:host-metrics",
action,
resourceType: "plugin",
success: true,
});
await entry(null, "plugin_db_client");
await entry(null, "plugin_kv_get");
await entry(null, "plugin_kv_set");
await entry("user-1", "plugin_db_client");
await entry(null, "plugin_as_user");
writeCount = 0;
expect(await repo.deleteRoutinePluginNoise()).toBe(2);
expect(writeCount).toBe(1);
const left = (
await repo.listPage({ filters: {}, limit: 10, offset: 0 })
).logs.map((log) => `${log.userId}:${log.action}`);
expect(left.sort()).toEqual([
"null:plugin_as_user",
"null:plugin_kv_set",
"user-1:plugin_db_client",
]);
expect(await repo.deleteRoutinePluginNoise()).toBe(0);
expect(writeCount).toBe(1);
});
it("keeps entries when their user is deleted, detaching instead of removing", async () => {
const repo = await createRepository();
@@ -10,6 +10,7 @@ vi.mock("../../../database/db/index.js", () => ({
}));
const {
createCurrentAuditLogRepository,
createCurrentSessionRepository,
createCurrentRepositoryContext,
createCurrentRepositoryWriteHook,
@@ -119,3 +120,42 @@ it("wires SQLite activity to the periodic flush and token changes to immediate p
else process.env[DATABASE_DIALECT_ENV] = saved;
}
});
// Audit rows land on every audited call; a forced save per row rewrote the
// whole SQLite file each time.
it("saves SQLite audit rows lazily instead of forcing a save per row", async () => {
const saved = process.env[DATABASE_DIALECT_ENV];
process.env[DATABASE_DIALECT_ENV] = "sqlite";
const { getDb } = await import("../../../database/db/index.js");
const { DatabaseSaveTrigger } =
await import("../../../utils/database-save-trigger.js");
const lazy = vi.spyOn(DatabaseSaveTrigger, "triggerSave").mockResolvedValue();
const force = vi.spyOn(DatabaseSaveTrigger, "forceSave").mockResolvedValue();
const query = {
insert: () => query,
values: async () => ({ changes: 1 }),
select: () => query,
from: async () => [{ count: 1 }],
};
vi.mocked(getDb).mockReturnValue(
query as unknown as ReturnType<typeof getDb>,
);
try {
const repo = createCurrentAuditLogRepository();
for (let i = 0; i < 100; i++) {
await repo.create({
userId: null,
username: "plugin:host-metrics",
action: "plugin_db_client",
resourceType: "plugin",
success: true,
});
}
expect(force).not.toHaveBeenCalled();
expect(lazy).toHaveBeenCalledTimes(100);
} finally {
vi.restoreAllMocks();
if (saved === undefined) delete process.env[DATABASE_DIALECT_ENV];
else process.env[DATABASE_DIALECT_ENV] = saved;
}
});
+42
View File
@@ -212,6 +212,48 @@ describe("ctx.db capability", () => {
});
});
// Every audit row rewrote the whole SQLite file, and pollers fetch the
// client before every query (2.9.1 wrote 100 GB in hours).
describe("ctx audit volume", () => {
it("audits the client handle once however often it is fetched", async () => {
grants.set("demo", ["db:own"]);
const { ctx } = contextFor("demo", ["db:own"]);
for (let i = 0; i < 100; i++) await ctx.db.client();
expect(
auditEntries.filter((row) => row.action === "plugin_db_client"),
).toHaveLength(1);
});
it("audits kv reads once but every kv write", async () => {
grants.set("demo", ["kv:own"]);
const { ctx } = contextFor("demo", ["kv:own"]);
for (let i = 0; i < 5; i++) await ctx.kv.get("k");
for (let i = 0; i < 3; i++) await ctx.kv.set("k", i);
const actions = auditEntries.map((row) => row.action);
expect(actions.filter((a) => a === "plugin_kv_get")).toHaveLength(1);
expect(actions.filter((a) => a === "plugin_kv_set")).toHaveLength(3);
});
it("still audits a refusal after the first success", async () => {
grants.set("demo", ["db:own"]);
const { ctx } = contextFor("demo", ["db:own"]);
await ctx.db.client();
grants.set("demo", []);
invalidatePluginPermissionCache("demo");
await expect(ctx.db.client()).rejects.toThrow();
const entries = auditEntries.filter(
(row) => row.action === "plugin_db_client",
);
expect(entries.map((row) => row.success)).toEqual([true, false]);
});
});
describe("ctx.kv limits", () => {
it("refuses a key over the length cap", async () => {
grants.set("demo", ["kv:own"]);
@@ -0,0 +1,41 @@
import { beforeEach, describe, expect, it, vi } from "vitest";
const deleteRoutinePluginNoise = vi.fn<() => Promise<number>>();
const forceSave = vi.fn<(reason: string) => Promise<void>>();
vi.mock("../../database/repositories/factory.js", () => ({
createCurrentAuditLogRepository: () => ({ deleteRoutinePluginNoise }),
}));
vi.mock("../../utils/database-save-trigger.js", () => ({
DatabaseSaveTrigger: { forceSave },
}));
const { runAuditNoiseCleanup } =
await import("../../upgrade/audit-noise-cleanup.js");
describe("runAuditNoiseCleanup", () => {
beforeEach(() => {
deleteRoutinePluginNoise.mockReset();
forceSave.mockReset().mockResolvedValue();
});
it("saves once after removing entries", async () => {
deleteRoutinePluginNoise.mockResolvedValue(9000);
await expect(runAuditNoiseCleanup()).resolves.toBe(9000);
expect(forceSave).toHaveBeenCalledOnce();
});
it("does not save when there was nothing to remove", async () => {
deleteRoutinePluginNoise.mockResolvedValue(0);
await expect(runAuditNoiseCleanup()).resolves.toBe(0);
expect(forceSave).not.toHaveBeenCalled();
});
it("never fails the boot", async () => {
deleteRoutinePluginNoise.mockRejectedValue(new Error("locked"));
await expect(runAuditNoiseCleanup()).resolves.toBe(0);
});
});
@@ -71,7 +71,21 @@ describe("DatabaseSaveTrigger", () => {
expect(DatabaseSaveTrigger.getStatus().pendingSave).toBe(false);
});
it("saves within the max wait even while writes keep coming", async () => {
it("saves at most once per 30 seconds while writes keep coming", async () => {
vi.useFakeTimers();
const save = vi.fn().mockResolvedValue(undefined);
DatabaseSaveTrigger.initialize(save);
// One sample every 3 seconds used to rewrite the database after each one.
for (let tick = 0; tick < 40; tick++) {
void DatabaseSaveTrigger.triggerSave("sample");
await vi.advanceTimersByTimeAsync(3000);
}
// 120 seconds: the first save after 2s, then one per 30s window.
expect(save.mock.calls.length).toBeGreaterThanOrEqual(4);
expect(save.mock.calls.length).toBeLessThanOrEqual(5);
});
it("still saves a steady stream of writes", async () => {
vi.useFakeTimers();
const save = vi.fn().mockResolvedValue(undefined);
DatabaseSaveTrigger.initialize(save);
@@ -79,7 +93,38 @@ describe("DatabaseSaveTrigger", () => {
void DatabaseSaveTrigger.triggerSave("sample");
await vi.advanceTimersByTimeAsync(1000);
}
expect(save.mock.calls.length).toBeGreaterThanOrEqual(1);
expect(save.mock.calls.length).toBeLessThanOrEqual(2);
});
it("saves a lone write after a quiet period within the debounce", async () => {
vi.useFakeTimers();
const save = vi.fn().mockResolvedValue(undefined);
DatabaseSaveTrigger.initialize(save);
void DatabaseSaveTrigger.triggerSave("first");
await vi.advanceTimersByTimeAsync(2000);
expect(save).toHaveBeenCalledTimes(1);
await vi.advanceTimersByTimeAsync(60_000);
void DatabaseSaveTrigger.triggerSave("later");
await vi.advanceTimersByTimeAsync(2000);
expect(save).toHaveBeenCalledTimes(2);
});
it("does not let a force save be throttled", async () => {
vi.useFakeTimers();
const save = vi.fn().mockResolvedValue(undefined);
DatabaseSaveTrigger.initialize(save);
void DatabaseSaveTrigger.triggerSave("sample");
await vi.advanceTimersByTimeAsync(2000);
expect(save).toHaveBeenCalledTimes(1);
await vi.advanceTimersByTimeAsync(10);
// Inside the 30s window, but a critical write saves right away.
vi.useRealTimers();
await DatabaseSaveTrigger.forceSave("user_create");
expect(save).toHaveBeenCalledTimes(2);
});
it("queues a force save behind an in-flight save", async () => {