From 853615af093afbffd10b26b5b96be8d92622fa21 Mon Sep 17 00:00:00 2001 From: LukeGus Date: Mon, 5 Oct 2026 20:10:09 -0500 Subject: [PATCH] fix: stop full database rewrites on every plugin db call --- src/backend/boot.ts | 4 ++ .../repositories/audit-log-repository.ts | 42 ++++++++++++++++- src/backend/database/repositories/factory.ts | 5 +- src/backend/plugins/ctx.ts | 26 ++++++---- .../repositories/audit-log-repository.test.ts | 36 ++++++++++++++ .../repositories/factory-context.test.ts | 40 ++++++++++++++++ src/backend/tests/plugins/ctx-db.test.ts | 42 +++++++++++++++++ .../tests/upgrade/audit-noise-cleanup.test.ts | 41 ++++++++++++++++ .../tests/utils/database-save-trigger.test.ts | 47 ++++++++++++++++++- src/backend/upgrade/audit-noise-cleanup.ts | 32 +++++++++++++ src/backend/utils/database-save-trigger.ts | 24 ++++------ 11 files changed, 313 insertions(+), 26 deletions(-) create mode 100644 src/backend/tests/upgrade/audit-noise-cleanup.test.ts create mode 100644 src/backend/upgrade/audit-noise-cleanup.ts diff --git a/src/backend/boot.ts b/src/backend/boot.ts index fffb5790d..04dd9bc98 100644 --- a/src/backend/boot.ts +++ b/src/backend/boot.ts @@ -68,4 +68,8 @@ export async function runCoreBootMigrations(): Promise { const { runExternalAutoProvisionMigration } = await import("./upgrade/external-auto-provision-migration.js"); await runExternalAutoProvisionMigration(); + + const { runAuditNoiseCleanup } = + await import("./upgrade/audit-noise-cleanup.js"); + await runAuditNoiseCleanup(); } diff --git a/src/backend/database/repositories/audit-log-repository.ts b/src/backend/database/repositories/audit-log-repository.ts index 1b01e6c29..2da752768 100644 --- a/src/backend/database/repositories/audit-log-repository.ts +++ b/src/backend/database/repositories/audit-log-repository.ts @@ -1,4 +1,15 @@ -import { and, asc, desc, eq, gte, inArray, lt, lte, sql } from "drizzle-orm"; +import { + and, + asc, + desc, + eq, + gte, + inArray, + isNull, + lt, + lte, + sql, +} from "drizzle-orm"; import { auditLogs } from "../db/schema.js"; import type { DatabaseContext } from "./database-context.js"; import { sqlTimestampDaysAgo } from "./sql-timestamp.js"; @@ -26,6 +37,17 @@ export const AUDIT_RETENTION_DAYS_ENV = "AUDIT_LOG_RETENTION_DAYS"; export const AUDIT_MAX_ENTRIES_ENV = "AUDIT_LOG_MAX_ENTRIES"; const DEFAULT_MAX_ENTRIES = 10000; + +// 2.9.1 logged these on every background plugin query and pushed real +// entries out of the capped log. They are now audited once per activation. +export const ROUTINE_PLUGIN_AUDIT_ACTIONS = [ + "plugin_db_client", + "plugin_db_refs", + "plugin_kv_get", + "plugin_kv_list", + "plugin_files_data_dir", + "plugin_settings_read_core", +]; const PRUNE_TARGET_RATIO = 0.9; function positiveIntEnv(key: string, env: NodeJS.ProcessEnv): number | null { @@ -166,6 +188,24 @@ export class AuditLogRepository { return rowsAffected(result); } + async deleteRoutinePluginNoise(): Promise { + AuditLogRepository.cachedCount = null; + const result = await this.context.drizzle + .delete(auditLogs) + .where( + and( + isNull(auditLogs.userId), + inArray(auditLogs.action, ROUTINE_PLUGIN_AUDIT_ACTIONS), + ), + ); + + if (rowsAffected(result) > 0) { + await this.afterWrite(); + } + + return rowsAffected(result); + } + private buildWhere(filters: AuditLogFilters) { const conditions = []; diff --git a/src/backend/database/repositories/factory.ts b/src/backend/database/repositories/factory.ts index f8e2d4845..7b8b6c508 100644 --- a/src/backend/database/repositories/factory.ts +++ b/src/backend/database/repositories/factory.ts @@ -78,7 +78,7 @@ export function createCurrentRepositoryWriteHook( * * Marks the in-memory database dirty and lets DatabaseSaveTrigger's existing * debounce coalesce the actual serialize+encrypt, instead of forcing one on - * every single sample. A lost 2-second window of telemetry on crash is + * every single sample. Losing up to 30 seconds of these on a crash is * acceptable; blocking the event loop that serves SSH traffic on every metric * sample is not. */ @@ -128,7 +128,8 @@ export function createCurrentApiKeyRepository(): ApiKeyRepository { export function createCurrentAuditLogRepository(): AuditLogRepository { return new AuditLogRepository( createCurrentRepositoryContext(), - createCurrentRepositoryWriteHook("audit_log_repository_write"), + // Rows land on every audited call; the audited action saves on its own. + createCurrentRepositoryLazyWriteHook("audit_log_repository_write"), ); } diff --git a/src/backend/plugins/ctx.ts b/src/backend/plugins/ctx.ts index ed55cfdab..81334536a 100644 --- a/src/backend/plugins/ctx.ts +++ b/src/backend/plugins/ctx.ts @@ -109,6 +109,11 @@ interface AuditOptions { action: string; /** Short description of the call shape. Never a value. */ details?: () => string; + /** + * Audit only the first success. For handles plugins fetch before every + * query: an audit row per call rewrote the whole database each time. + */ + once?: boolean; } /** @@ -124,6 +129,7 @@ function guarded( fn: (...args: Args) => Promise, options: AuditOptions, ): (...args: Args) => Promise { + let audited = false; return async (...args: Args): Promise => { // A refusal is audited inside assertCapability, under this action. await assertCapability( @@ -135,7 +141,10 @@ function guarded( try { const result = await fn(...args); - await writeAudit(manifest, options, { success: true }); + if (!options.once || !audited) { + audited = true; + await writeAudit(manifest, options, { success: true }); + } return result; } catch (error) { await writeAudit(manifest, options, { @@ -242,7 +251,7 @@ export function createPluginContext( return null; } }, - { action: "kv_get" }, + { action: "kv_get", once: true }, ); const kvSet = guarded( @@ -296,7 +305,7 @@ export function createPluginContext( await import("../database/repositories/factory.js"); return createCurrentPluginStorageRepository().listKeys(pluginId); }, - { action: "kv_list" }, + { action: "kv_list", once: true }, ); const filesDataDir = guarded( @@ -309,7 +318,7 @@ export function createPluginContext( await fs.mkdir(dir, { recursive: true }); return dir; }, - { action: "files_data_dir" }, + { action: "files_data_dir", once: true }, ); const dbDefine = guarded( @@ -329,7 +338,7 @@ export function createPluginContext( const { getDb } = await import("../database/db/index.js"); return getDb(); }, - { action: "db_client" }, + { action: "db_client", once: true }, ); // The one settings call that leaves the plugin's own namespace, so the one @@ -341,6 +350,7 @@ export function createPluginContext( { action: "settings_read_core", details: () => "read a core server setting", + once: true, }, ); @@ -359,7 +369,7 @@ export function createPluginContext( userRoles: schema.userRoles, }; }, - { action: "db_refs" }, + { action: "db_refs", once: true }, ); const desktopOpenIsolatedWindow = guarded( @@ -488,8 +498,8 @@ export function createPluginContext( define: (definition) => dbDefine(definition) as never, client: () => dbClient() as never, refs: () => dbRefs() as never, - // Gated but not audited: it follows every write, and the write itself - // went through a client() call that already left an audit line. + // Gated but not audited: it follows every write, and client() was + // already audited when the plugin first asked for it. persist: async (options) => { await assertCapability(pluginId, "db:own", manifest.capabilities); if (!needsExplicitPersist(resolveDatabaseDialect())) return; diff --git a/src/backend/tests/database/repositories/audit-log-repository.test.ts b/src/backend/tests/database/repositories/audit-log-repository.test.ts index 2de30072b..565cf9dca 100644 --- a/src/backend/tests/database/repositories/audit-log-repository.test.ts +++ b/src/backend/tests/database/repositories/audit-log-repository.test.ts @@ -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(); diff --git a/src/backend/tests/database/repositories/factory-context.test.ts b/src/backend/tests/database/repositories/factory-context.test.ts index fbd899b6c..79273384e 100644 --- a/src/backend/tests/database/repositories/factory-context.test.ts +++ b/src/backend/tests/database/repositories/factory-context.test.ts @@ -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, + ); + 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; + } +}); diff --git a/src/backend/tests/plugins/ctx-db.test.ts b/src/backend/tests/plugins/ctx-db.test.ts index 4de1200f1..285659d90 100644 --- a/src/backend/tests/plugins/ctx-db.test.ts +++ b/src/backend/tests/plugins/ctx-db.test.ts @@ -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"]); diff --git a/src/backend/tests/upgrade/audit-noise-cleanup.test.ts b/src/backend/tests/upgrade/audit-noise-cleanup.test.ts new file mode 100644 index 000000000..35bfad3ff --- /dev/null +++ b/src/backend/tests/upgrade/audit-noise-cleanup.test.ts @@ -0,0 +1,41 @@ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const deleteRoutinePluginNoise = vi.fn<() => Promise>(); +const forceSave = vi.fn<(reason: string) => Promise>(); + +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); + }); +}); diff --git a/src/backend/tests/utils/database-save-trigger.test.ts b/src/backend/tests/utils/database-save-trigger.test.ts index 64791d5c2..90dcd2702 100644 --- a/src/backend/tests/utils/database-save-trigger.test.ts +++ b/src/backend/tests/utils/database-save-trigger.test.ts @@ -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 () => { diff --git a/src/backend/upgrade/audit-noise-cleanup.ts b/src/backend/upgrade/audit-noise-cleanup.ts new file mode 100644 index 000000000..b4b4325cd --- /dev/null +++ b/src/backend/upgrade/audit-noise-cleanup.ts @@ -0,0 +1,32 @@ +/** + * Clears the audit rows 2.9.1 wrote on every background plugin query. + * + * They filled the capped audit log and pushed real entries out. Idempotent, + * so it runs on every boot, before plugins activate and audit again. + */ + +import { databaseLogger } from "../utils/logger.js"; +import { getErrorMessage } from "../utils/error-message.js"; +import { createCurrentAuditLogRepository } from "../database/repositories/factory.js"; +import { DatabaseSaveTrigger } from "../utils/database-save-trigger.js"; + +export async function runAuditNoiseCleanup(): Promise { + try { + const removed = + await createCurrentAuditLogRepository().deleteRoutinePluginNoise(); + if (removed > 0) { + await DatabaseSaveTrigger.forceSave("audit_noise_cleanup"); + databaseLogger.info("Removed routine plugin audit entries", { + operation: "audit_noise_cleanup", + removed, + }); + } + return removed; + } catch (error) { + databaseLogger.warn("Failed to remove routine plugin audit entries", { + operation: "audit_noise_cleanup_failed", + error: getErrorMessage(error), + }); + return 0; + } +} diff --git a/src/backend/utils/database-save-trigger.ts b/src/backend/utils/database-save-trigger.ts index 1125e78dc..2d6c5a9fd 100644 --- a/src/backend/utils/database-save-trigger.ts +++ b/src/backend/utils/database-save-trigger.ts @@ -3,7 +3,9 @@ import { getErrorMessage } from "./error-message.js"; import { databaseLogger } from "./logger.js"; const DEBOUNCE_MS = 2000; -const MAX_DEBOUNCE_WAIT_MS = 30_000; +// Every save rewrites the whole database file, so background writes (metrics +// samples, audit rows) may only cause one save per this window. +const MIN_LAZY_SAVE_GAP_MS = 30_000; export class DatabaseSaveTrigger { private static saveFunction: (() => Promise) | null = null; @@ -11,7 +13,7 @@ export class DatabaseSaveTrigger { private static pendingSave = false; private static activeSave: Promise | null = null; private static saveTimeout: NodeJS.Timeout | null = null; - private static firstTriggerAt: number | null = null; + private static lastSaveAt = 0; private static _dirty = false; private static batch = new AsyncLocalStorage<{ open: boolean; @@ -49,22 +51,16 @@ export class DatabaseSaveTrigger { this._dirty = true; - if (this.saveTimeout) { - clearTimeout(this.saveTimeout); - } + // A save already pending picks this write up too. + if (this.saveTimeout) return; - // Each call pushes the save back, so steady writes (samples every few - // seconds) would keep it from ever running. Cap how long it can wait. - const now = Date.now(); - this.firstTriggerAt ??= now; const delay = Math.max( - 0, - Math.min(DEBOUNCE_MS, this.firstTriggerAt + MAX_DEBOUNCE_WAIT_MS - now), + DEBOUNCE_MS, + this.lastSaveAt + MIN_LAZY_SAVE_GAP_MS - Date.now(), ); this.saveTimeout = setTimeout(async () => { this.saveTimeout = null; - this.firstTriggerAt = null; try { await this.runSave(); @@ -123,7 +119,6 @@ export class DatabaseSaveTrigger { clearTimeout(this.saveTimeout); this.saveTimeout = null; } - this.firstTriggerAt = null; try { await this.runSave(); @@ -156,6 +151,7 @@ export class DatabaseSaveTrigger { .finally(() => new Promise((resolve) => setImmediate(resolve))); this.activeSave = save; this.pendingSave = true; + this.lastSaveAt = Date.now(); try { await save; @@ -184,7 +180,7 @@ export class DatabaseSaveTrigger { clearTimeout(this.saveTimeout); this.saveTimeout = null; } - this.firstTriggerAt = null; + this.lastSaveAt = 0; this.pendingSave = false; this.activeSave = null;