fix(audit): prune expired events in bounded batches

[davlaw]

Addresses the second half of #604.

Problem

prune_locked() issued a single open-ended statement:

"DELETE FROM audit_events WHERE occurred_at < ?;"

while holding the global database mutex — and it is reached from the audit insert path (db_audit.c:182, the hourly automatic prune), not from a background job.

Today that's harmless, because the 365-day default means the statement matches nothing on essentially every install. It stops being harmless the moment it has real work:

• a backlog finally ages past the retention window, or
• an administrator lowers audit_retention_days on an existing table

…at which point one ordinary audit write blocks every other database user until the delete completes.

I measured this on the 5.9M-row audit_events table from #604, with the service stopped so nothing was competing for the lock:

DELETE FROM audit_events WHERE action='live.view' AND occurred_at < ...;
  5,333,676 rows  --  real 2m31s

Two and a half minutes of held mutex, reachable from a routine audit write. On that install it would have stalled recording, detection and the HTTP API simultaneously.

Change

Delete in capped batches (AUDIT_PRUNE_BATCH_ROWS = 2000) under a soft time budget (AUDIT_PRUNE_BUDGET_MS = 250), so the work per pass is proportional to the batch size rather than to the backlog. The budget is checked between statements, so it limits how many batches a pass runs — it is not a wall-clock bound on mutex hold time: a batch already in flight, or a slow/contended database, can overrun it.

When the budget expires with rows still eligible, prune_locked() reports more_remaining and the caller shortens the insert-path eligibility interval from 1 hour to 60s, so a backlog drains steadily instead of one batch per hour. This is not a scheduled job: passes are driven by db_audit_append(), so an install with no audit traffic holds a backlog until writes resume. Once caught up it returns to the hourly cadence, leaving steady-state behaviour unchanged.

The batch statement uses id IN (SELECT ... ORDER BY id LIMIT ?) rather than DELETE ... LIMIT, since the latter requires SQLITE_ENABLE_UPDATE_DELETE_LIMIT, which isn't enabled in every SQLite build this project links against. idx_audit_events_occurred covers the inner scan.

One deliberate behaviour change worth calling out: the explicit prune behind the retention-settings endpoint is now bounded by the same budget, so on a large backlog it returns a partial pruned_events count and the remainder drains over the following ticks. That seemed clearly preferable to an admin request that freezes the database for minutes, but say the word if you'd rather that path stayed unbounded.

Testing

test_retention_drains_large_backlog_without_touching_live_events builds a backlog larger than one batch plus events inside the retention window, drains it through repeated prunes, and asserts the backlog is fully removed, the live events are untouched, and the loop terminates.

Verified it actually fails on a broken implementation rather than passing vacuously — inverting the cutoff comparison to occurred_at >= ? produces:

test_retention_drains_large_backlog_without_touching_live_events:FAIL: Expected 0 Was 2100

It's tagged with its own target_uuid so it neither depends on nor disturbs rows left by other tests in the binary.

What it does not assert is the mutex hold time itself — that's inherently timing-dependent, so the tests cover correctness, termination, batching, the query plan and the insert-path cadence rather than a time bound. test_audit_log 15/15, test_db_backup and test_api_handlers_recordings_playback also green, full target builds clean.

Not included

The live.view volume question from #604 (a durable audit row per live-view request, ~400k rows/day on the install that surfaced this) is left alone — that's a call about what the audit trail is meant to guarantee, not something to change from the outside. This PR only makes pruning safe whenever it does run.

🤖 Generated with Claude Code

[matteius]

I recommend addressing the query plan and regression coverage before merging. Reviewed at 6f1e4b3e451f5487fdc19e30e5997fc524ba4a4c.

1. The batch query introduces a full-table scan. In db_audit.c:111, ORDER BY id makes SQLite choose SCAN audit_events for the inner query instead of using the retention index. When no rows are expired, or fewer than 2,000 remain, it scans every surviving row while the global database mutex is held. This regresses the common no-work prune case.

   Using SQLite 3.46.1, the project's audit schema, and one million unexpired synthetic rows in memory, I measured:

   Query	Elapsed time
   Existing unbounded delete, matching no rows	0.013 ms
   PR's batched delete	93.5 ms
   Batch ordered by occurred_at, id	0.018 ms

   The PR query executed approximately three million SQLite VM operations. Changing the inner ordering to ORDER BY occurred_at, id used the existing covering index, idx_audit_events_occurred. The scan versus index distinction also held after ANALYZE. Please make that ordering change and add coverage for a large table with few or no expired rows. These timings are local measurements, not storage-independent bounds.

2. The new backlog test does not protect the batching behavior. I temporarily substituted the original unbounded DELETE into prune_locked() and all 12 audit tests still passed, including test_retention_drains_large_backlog_without_touching_live_events. The test verifies deletion correctness, but would not catch removal of the central behavior this PR adds. A controllable clock could force budget exhaustion deterministically, allowing assertions for partial deletion, subsequent draining, and the 60-second-to-hourly cadence transition.

Two behavior claims also need qualification:

• 250 ms is a soft budget. It is checked after sqlite3_step() completes; a single statement can exceed it while holding the mutex. The comments and description should not promise a maximum hold time regardless of storage speed.
• 60 seconds is an eligibility interval, not a scheduled job. Follow-up pruning requires another audit insertion. After an explicit retention update returns a partial count, a quiet installation can retain the unfinished backlog until further audit traffic arrives. Please make that limitation explicit, or arrange independent follow-up maintenance if draining without traffic is intended.

Validation: a fresh isolated build of this PR passed test_audit_log, test_db_backup, and test_api_handlers_recordings_playback (SOD, LiteRT, MQTT, and SSL disabled). After the mutation check, I restored the exact PR source, rebuilt, and reran the audit tests successfully.

[davlaw]

Thanks — all four points were correct, and the query-plan one was a genuine regression I introduced in the case that matters most. Fixed in e48dbfcb.

1. Full-table scan. Confirmed independently before changing anything. EXPLAIN QUERY PLAN on the project's schema:

ORDER BY id             -> SCAN audit_events
ORDER BY occurred_at,id -> SEARCH audit_events USING COVERING INDEX idx_audit_events_occurred (occurred_at<?)

and timing on 1M unexpired rows, same shape as yours:

Query	Elapsed
Existing unbounded delete, matching no rows	0.000 s
PR's batched delete (ORDER BY id)	0.048 s
ORDER BY occurred_at, id	0.001 s

Changed to ORDER BY occurred_at, id. I also moved the statement into AUDIT_PRUNE_BATCH_SQL so the new plan test asserts against the exact string the implementation executes rather than a copy in the test that can drift out of sync.

New test test_prune_batch_query_uses_the_retention_index populates a table with nothing expired, asserts the prune deletes 0, and asserts the plan uses the covering index and contains no SCAN audit_events. Restoring ORDER BY id fails it:

test_prune_batch_query_uses_the_retention_index:FAIL. prune batch must use idx_audit_events_occurred

A timing assertion would have been flaky in CI, and deletion counts alone can't distinguish a scan from a seek — hence asserting on the plan.

2. The test didn't protect the batching. You're right, and I'd rather have caught that myself. I reproduced your mutation: substituting the unbounded DELETE passed all 12 tests.

Added test_prune_stops_on_budget_and_resumes_until_drained, which takes your controllable-clock suggestion: a test-only seam forces the budget to 0, so the deadline has already passed when the first batch returns and exactly one batch is deleted per pass. It then asserts partial deletion, the shortened backlog cadence, the full drain across subsequent passes, and the return to the hourly cadence. Under the unbounded substitution it now fails:

test_prune_stops_on_budget_and_resumes_until_drained:FAIL: Expected 2000 Was 4000

The budget setter and interval getter are declared extern in the test file rather than in the public header, matching how the same point was resolved on #595.

3. Soft budget. Corrected. The header and function comments now say the budget is checked between statements, so it bounds how many batches a pass runs rather than the pass itself — a batch already in flight can overrun it — and explicitly promise no maximum hold time regardless of storage speed. The PR description overstated this too.

4. Eligibility interval, not a schedule. Corrected in both db_audit_prune() and the header: the shortened interval only makes the next prune eligible sooner, passes are driven from db_audit_append(), and an installation quiet enough to stop writing audit events will hold the remaining backlog until audit traffic resumes. Also documented that an explicit retention update returns a partial deleted_count in that case. I did not add an independent maintenance tick — that's a larger design choice and seemed like yours to make; happy to add one if you'd like draining to be traffic-independent.

Verification: test_audit_log 14/14, plus test_db_backup and test_api_handlers_recordings_playback green, full target builds clean. Both new tests were checked against the specific mutation each is meant to catch rather than only in the passing direction.

🤖 Generated with Claude Code

[matteius]

@davlaw I think we can make it configurable by an admin which audit entries are required, and we can explore additional optimizations for the noisy ones.

[Copilot]

🟡 Changes recommended

The wall-clock mutex bound is not guaranteed, and automatic cadence plus test-cleanup coverage remain incomplete.

Get a fresh assessment by requesting another Copilot review.

Pull request overview

This PR replaces unbounded audit-event pruning with indexed, budgeted batches to reduce database mutex contention.

Changes:

• Deletes events in capped 2,000-row batches with a 250 ms budget.
• Retries more frequently while a backlog remains.
• Adds pruning, draining, and query-plan tests.

File summaries

File	Summary
tests/unit/test_audit_log.c	Adds pruning behavior and query-plan regression tests.
src/database/db_audit.c	Implements bounded pruning and backlog cadence.
include/database/db_audit.h	Defines prune limits and batch SQL.

Review details

Suppressed comments (2)

src/database/db_audit.c:254

• The new cadence branch is only exercised through db_audit_prune() in the added tests. No test drives db_audit_append() after a backlog prune to verify that more_remaining changes the insert-path eligibility from one hour to 60 seconds and then restores it after catch-up, so this production-critical path could regress while the suite stays green. Add a deterministic clock/interval seam and exercise the automatic caller.

    if (rc == SQLITE_DONE && now - last_automatic_prune_at >= automatic_prune_interval) {
        int deleted = 0;
        bool more_remaining = false;
        if (prune_locked(db, &deleted, &more_remaining) == 0) {
            last_automatic_prune_at = now;

tests/unit/test_audit_log.c:236

• This sets a process-global prune-budget override, but the reset at line 256 is skipped whenever any assertion below line 236 returns early. A failed test can therefore leave later tests running with a zero budget and altered pruning cadence; reset the seam unconditionally from the test fixture teardown or an unconditional cleanup path.

    db_audit_set_prune_budget_ms_for_testing(0);

• Files reviewed: 3/3 changed files
• Comments generated: 1
• Review effort level: Lite

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[davlaw]

Agreed — the budget is checked only after sqlite3_step() returns, so it can't bound a single batch that is slow on I/O or waiting on a busy timeout. I've narrowed the guarantee rather than trying to enforce it inside the statement: the code comments already said the budget "bounds how many batches a pass runs, not the pass itself" and that "no maximum hold time is promised", and the PR description, which still claimed a bound "regardless of storage speed", now says explicitly that it is not a wall-clock bound on mutex hold time.

What the change does guarantee is a row-count cap per statement (2,000 via the indexed occurred_at, id ordering) plus a between-statement budget, so work per pass is proportional to the batch size instead of the backlog. Interrupting a statement mid-flight via a progress handler would roll back that batch's work and needs its own retry/backoff design, so I've left it out of scope here.

[davlaw]

Second Copilot round addressed in e53c98fd — one inline comment plus the two it suppressed, all valid.

Wall-clock bound (inline). Narrowed the claim rather than enforcing it mid-statement; replied on the thread. The description no longer promises a hold-time bound.

Insert-path cadence untested (suppressed). Production pruning runs from db_audit_append(), but only db_audit_prune() was exercised. New test_automatic_prune_on_append_follows_backlog_cadence uses a test-only seam to place the eligibility window, then asserts through appends that a budget-limited pass shortens the interval to 60s, an append inside that window does not prune, an append past it runs the next batch, and a pass that finds nothing restores the hourly cadence. Checked in the failing direction: making the insert path ignore more_remaining fails it with Expected 60 Was 3600.

Seam leak on assertion failure (suppressed). The budget override was only reset on the test's success path. tearDown() now resets it and the automatic prune state unconditionally.

test_audit_log 15/15, test_db_backup and test_api_handlers_recordings_playback green, full target builds clean.

On your earlier suggestion of letting admins choose which audit entries are required: happy to take that on in a separate PR if you'd like it from me, but I don't want to duplicate it if you're already planning it.

🤖 Generated with Claude Code

[matteius]

@davlaw I have family in town so won't have time to work on it for a bit ... feel free to give it a shot!