diff --git a/CLAUDE.md b/CLAUDE.md index 1a02e3b4..1f3252d4 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -190,7 +190,7 @@ spec for each is `docs/requirements/Component-.md`, and `README.md` carrie - Debug view: real-time streaming via DebugStreamBridgeActor + gRPC (events via `SiteStreamGrpcClient`, snapshot via the `SiteCommandService` query surface — `QueryReply.DebugViewSnapshot`). Health dashboard: 10s polling timer. Deployment status: real-time push via SignalR. - Health reports: 30s interval, 60s offline threshold, monotonic sequence numbers, raw error counts per interval. - Dead letter monitoring as a health metric. -- Site Event Logging: 30-day retention, 1GB storage cap, daily purge, paginated queries with keyword search. +- Site Event Logging: 30-day retention, 1GB storage cap, daily purge, paginated queries with keyword search. **The cap measures `site_events` + its four indexes, NOT the consolidated LocalDb file** (register row 81, 2026-08-17): whole-file measurement made the trim unwinnable on a replicated node — each batch freed event pages while adding an equal count of oplog rows + tombstones to the same file, so it stopped 2.5x over a 64 MB cap and a node with a down peer could not enforce the cap at all. `dbstat` (the exact per-table measurement) is **NOT compiled into the bundled `SQLitePCLRaw.lib.e_sqlite3`** — probed and pinned by `SqliteCapabilityTests`, so don't reach for it — the footprint is modelled from sampled row width instead (−0.8%…+12.8%, biased high). Consequence: `MaxStorageMb` no longer bounds the data volume alone; LocalDb bookkeeping is separate overhead bounded by `MaxOplogRows`/`TombstoneRetention` and is deliberately not this component's job. Decision: `docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md`. - Notification Outbox KPIs are central-computed point-in-time from the `Notifications` table (global + per-source-site): queue depth, stuck count, parked count, delivered-last-interval, oldest-pending age. - Stuck = `Pending`/`Retrying` older than a configurable age threshold (default 10 min) — display-only (KPI count + row badge), no escalation/alerting. - Headline KPI tiles surface on the Health dashboard; a new Central UI Notification Outbox page offers a queryable list with Retry/Discard actions on parked notifications. diff --git a/docs/deployment/topology-guide.md b/docs/deployment/topology-guide.md index b2e69bff..127d8ea9 100644 --- a/docs/deployment/topology-guide.md +++ b/docs/deployment/topology-guide.md @@ -273,6 +273,13 @@ history had expired. An unreplicated node logs only the first line. If a backlog spike has no such line near it in the active node's log, the purge is *not* the explanation and the spike is worth investigating. +The second line is emitted **once per purge tick**, and its count covers the retention purge and +the storage-cap trim together. If you are comparing it against the `Purged N events older than…` +line above it, expect the two numbers to differ whenever the cap trim also ran — the note reports +the tick's whole contribution to the oplog, which is what a backlog spike is made of. (Through +2026-08-16 the note was emitted per phase, so a tick that ran both produced two near-identical +lines; register row 84.) + **A tick that hit the ceiling adds a Warning**, rate-limited to one line per 15 minutes so a converging backlog does not flood the log: @@ -513,6 +520,33 @@ hardening and needs no change to the key design. | Site node | 2 cores | 4 GB | 20 GB | SQLite databases grow with S&F | | SQL Server | 4 cores | 16 GB | 100 GB | Shared across central cluster | +#### Sizing a site's data volume — `MaxStorageMb` is not the whole story + +`ScadaBridge:SiteEventLog:MaxStorageMb` (default **1 GB**) bounds **`site_events` and its four +indexes**, and nothing else. It is deliberately *not* a cap on the consolidated LocalDb file +(register row 81 — decision record +`docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md`). Before that change it did +measure the whole file, which on a replicated node made the cap unenforceable: the trim's own CDC +oplog rows and tombstones grew the file as fast as the deletes shrank it, and the trim stopped +2.5x over cap. Tying the event log's budget to the peer's liveness was the defect, not a feature +worth preserving. + +So budget the volume as the **sum** of: + +- **`MaxStorageMb`** — the event log proper. +- **LocalDb replication bookkeeping** — `__localdb_oplog` and `__localdb_row_version`, bounded + separately by `LocalDb:Replication:MaxOplogRows` (default 1 000 000) and `TombstoneRetention` + (default 7 days). This is transient: it drains as the peer acks and as tombstones expire, but it + is not small during a burst. Measured worst case (register row 34): purging a full 1 GB event log + left **707 MB** of bookkeeping in the file. Unreplicated sites carry none of this — they have no + capture triggers at all. +- **The other eight consolidated tables** plus the separate, unreplicated audit database at + `AuditLog:SiteWriter:DatabasePath`. + +The 20 GB figure above has ample headroom for all three at default settings. Raising +`MaxStorageMb` on a replicated site should be paired with a look at the oplog settings, not done +in isolation. + ### Network Bandwidth - Health reports: ~1 KB per site per 30 seconds = negligible diff --git a/docs/plans/2026-08-15-site-events-purge-burst-measurement.md b/docs/plans/2026-08-15-site-events-purge-burst-measurement.md index d8d72360..89658838 100644 --- a/docs/plans/2026-08-15-site-events-purge-burst-measurement.md +++ b/docs/plans/2026-08-15-site-events-purge-burst-measurement.md @@ -204,6 +204,18 @@ practice shared with replication bookkeeping that the event log does not own. A measure `site_events`' own pages (e.g. `dbstat`) rather than the file, which is a change to the cap's semantics and deserves its own decision. Reported for the register; no row added here. +> **Postscript (2026-08-17) — fixed; register row 81 closed.** The cap now measures `site_events` +> and its four indexes only. One correction to the suggestion above: **`dbstat` turned out to be +> unavailable.** It is a compile-time option and the bundled `SQLitePCLRaw.lib.e_sqlite3` +> (SQLite 3.53.3) does not enable it — `PRAGMA compile_options` lists no `ENABLE_DBSTAT_VTAB`, and +> neither `dbstat` nor `sqlite_dbpage` appears in `pragma_module_list`. The table's footprint is +> therefore *modelled* from sampled row width rather than measured, at −0.8 %…+12.8 % accuracy +> against the numbers in §3.4, biased high on purpose. The "size did not decrease" guard survives, +> re-based onto the table-scoped metric so replication bookkeeping can no longer trip it. Decision +> record, including the probe evidence and why a different SQLite build was rejected: +> `docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md`. §3.4's replicated row is left +> as measured — it is the record of the defect, not of current behaviour. + ## 6. Verification - Fail-before: the new behavioural tests do not compile against pre-fix `EventLogPurgeService` diff --git a/docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md b/docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md new file mode 100644 index 00000000..357ebc6e --- /dev/null +++ b/docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md @@ -0,0 +1,264 @@ +# `site_events` storage cap — what the cap measures (register row 81) + +**Date:** 2026-08-17 +**Row:** deferred-work register #81 — *"the storage cap fights its own oplog."* +**Outcome:** cap semantics changed. `ScadaBridge:SiteEventLog:MaxStorageMb` now bounds +**`site_events` and its four indexes**, not the whole consolidated LocalDb file. `dbstat` — the +exact measurement the register proposed — turned out to be **unavailable in the SQLite this +solution ships**, so the table's footprint is *modelled* from sampled row width. This memo records +the probe that ruled `dbstat` out, the model, its measured accuracy, and the new meaning of the +wipe-prevention guard. + +--- + +## 1. The defect + +Since LocalDb Phase 1/2 the site keeps ten tables in one SQLite file at `LocalDb:Path`, alongside +LocalDb's own `__localdb_oplog`, `__localdb_row_version` and `__localdb_snapshot_state` +bookkeeping. `EventLogPurgeService.GetDatabaseSizeBytes()` measured +`page_count − freelist_count` over **that whole file** and compared it to `MaxStorageMb`. + +On a replication-enabled node the cap trim therefore fought itself. Every 1000-row batch freed +~390 KB of `site_events` pages *and* pushed ~1000 rows into `__localdb_oplog` plus ~1000 +row-version tombstones into the same file. The measured size did not fall, the existing +"size did not decrease across an iteration" guard fired, and the trim stopped — with the cap +unmet. + +Measured 2026-08-16 during the row-34 work +(`docs/plans/2026-08-15-site-events-purge-burst-measurement.md` §3.4/§5), 64 MB cap, 400 000 rows: + +| Replicated? | Events deleted | Remaining | Size before → after | Reached the cap? | +| --- | ---: | ---: | --- | --- | +| no | 248 000 | 152 000 | 158.0 MB → 66.98 MB | **yes** (cap 67.11 MB) | +| yes | 174 000 | 226 000 | 203.6 MB → 167.7 MB | **no — stopped 2.5x over cap** | + +Two consequences, both real: + +1. **A node whose peer is down cannot enforce its event-log cap at all.** Nothing drains the + oplog, so the file never shrinks and the guard stops the trim every tick, forever. +2. **The "1 GB event log" budget was in practice shared with replication bookkeeping the event + log does not own.** Worse, the direction of the coupling is backwards: a *replication fault* + (peer down, oplog piling up) would, under a naive "just keep deleting" fix, cause operational + event history to be destroyed. The cap must not be a function of the peer's health. + +The old guard was not the bug — it was doing its job, preventing the table being wiped in pursuit +of an unreachable target. The bug is that the target was unreachable, because the metric was +wrong. + +## 2. `dbstat` is not available — the decision this memo turns on + +The register proposed `SELECT sum(pgsize) FROM dbstat WHERE name='site_events'`. `dbstat` is a +**compile-time option** (`SQLITE_ENABLE_DBSTAT_VTAB`), and it was verified before any +implementation was written. It is **not enabled** in the native library this solution ships +(`SQLitePCLRaw.lib.e_sqlite3`, the security-pinned 2.1.12 build referenced by both +`ZB.MOM.WW.ScadaBridge.SiteEventLogging` and its test project). + +Probed live against a real file, SQLite **3.53.3**: + +``` +PRAGMA compile_options -> no ENABLE_DBSTAT_VTAB + (ENABLE_FTS3/4/5, RTREE, GEOPOLY, SESSION, PREUPDATE_HOOK, … present) +pragma_module_list -> 10 modules: fts3, fts3tokenize, fts4, fts4aux, fts5, fts5vocab, + geopoly, pragma_module_list, rtree, rtree_i32 +SELECT sum(pgsize) FROM dbstat -> SQLite Error 1: 'no such table: dbstat' +SELECT … FROM dbstat('main') WHERE name=… -> SQLite Error 1: 'no such table: dbstat' +``` + +`sqlite_dbpage` — the other route to per-table page attribution — is absent for the same reason. +The module list is non-empty, so this is a genuine absence and not an empty-result artefact. + +**This is pinned by a committed test**, `SqliteCapabilityTests.DbStat_IsNotAvailable_…`, written to +fail if `dbstat` ever appears. If it does, the right move is to delete the model in §3 and measure +exactly; the test's own comment says so. + +Alternatives considered and rejected: + +- **Switch to a SQLite build that enables `dbstat`** (system `libsqlite3` via + `SQLitePCLRaw.bundle_sqlite3`, or a vendored native build). Rejected: the provider is shared with + `ZB.MOM.WW.LocalDb` and every other SQLite consumer in the product, so this trades a storage-cap + accuracy problem for fleet-wide version skew across macOS dev boxes and the Debian-based runtime + image — a disproportionate blast radius for a coarse safety valve. +- **Give `site_events` its own file again.** Reverses LocalDb Phase 1/2 consolidation and removes + the table from CDC replication. Out of the question. +- **Maintain a running byte counter in the writer, or via triggers.** The writer is not the only + thing that inserts into `site_events` (replication applies remote rows), a counter does not + survive a restart, and adding our own triggers to a `RegisterReplicated` table is hazardous — + LocalDb builds its capture triggers from the column list at registration time and extra triggers + would also fire on replicated applies. +- **Keep the whole-file metric and simply stop re-measuring mid-loop** (compute a delete plan once + and execute it). This makes the trim terminate, but it makes the *event log* pay for bookkeeping + bytes: an oplog inflated by a down peer would drive aggressive deletion of operational history. + That is consequence 2 above, made worse rather than fixed. + +## 3. What the cap measures now + +`EventLogPurgeService.EstimateSiteEventsSize()` returns the live row count and modelled bytes per +row. `MaxStorageMb` is compared against `rowCount × bytesPerRow`. + +Row width is **sampled** — `SizeSampleRows` (500) rows from each end of the table, head and tail. +The head is what the oldest-first trim will actually delete; the tail catches an event stream whose +shape has drifted. Widths are taken with `octet_length()` (SQLite 3.43+), not `length()`, which +counts characters and would under-size any multi-byte UTF-8 message; a second committed test pins +that function's availability. + +The table term is computed as **whole pages**, `ceil(rows / rowsPerPage) × pageSize`, rather than +as a flat bytes-per-row rate: + +``` +usablePerPage = (pageSize - 35) * 0.78 // max-local-payload rule × measured mean page fill +avgCellBytes = avgPayloadBytes + 16 // payload-length varint, rowid varint, cell pointer +rowsPerPage = max(1, floor(usablePerPage / avgCellBytes)) +tableBytes = ceil(rowCount / rowsPerPage) * pageSize +indexBytes = rowCount * (avgIndexedBytes + 8 * 4) / 0.75 +estimate = min(tableBytes + indexBytes, wholeFileLogicalBytes) +``` + +Whole pages rather than a rate because that term **dominates once rows approach half a page**: a +2 KB row cannot be packed two-to-a-page, so each one wastes the remainder. A linear model +underestimates that case by ~40 % (measured), and underestimating is the failure direction that +matters for a cap. + +**Index pages count against the cap — deliberately.** Measured, the four indexes are ~34 % of +`site_events`' total footprint (397.2 vs 260.9 bytes/row with and without them, same 200 000 rows), +and the 1 GB default was sized against the 393 bytes/row figure from row 34, which already included +them. Excluding index pages would silently raise real disk consumption by about a third at an +unchanged setting. The index term is driven by the *sampled* widths of the four indexed columns, so +an event stream that leaves `instance_id` null is charged less than one that fills it. + +**Clamped by the file.** The whole-file logical size is a true upper bound on any single table's +pages, so the model is capped by it. This can only ever correct an over-estimate downward, and it +cannot reintroduce the row-81 defect: on a replicated node the file is *larger* than +`site_events`, never smaller, so the clamp does not bind there. + +`GetDatabaseSizeBytes()` survives, renamed in meaning rather than in signature: it is the whole +consolidated file's logical size, used for the clamp and as a diagnostic. It is no longer what the +cap compares against. + +### 3.1 Measured accuracy + +Calibration seeded realistic rows into a real file and measured `page_count`/`freelist_count`/ +`page_size`. Two independent cross-checks against row 34's harness: the baseline workload came out +at **397.2 bytes/row** against row 34's independently measured **393**, and the row-count-at-1 GB +figure follows. + +| Workload | rows | actual bytes/row | payload bytes/row | +| --- | ---: | ---: | ---: | +| 1-in-10 details @200 B (baseline) | 200 000 | 397.2 | 187.9 | +| same, **no indexes** | 200 000 | 260.9 | 187.9 | +| no details at all | 200 000 | 373.5 | 167.7 | +| details on every row @200 B | 200 000 | 597.7 | 367.7 | +| details on every row @2 KB | 50 000 | 4295.2 | 2215.7 | +| 1-in-10 details @4 KB | 50 000 | 824.7 | 583.0 | +| small table | 5 000 | 396.5 | 189.6 | + +The shipped model, scored against a **differential** measurement of the table's real page cost +(file measured with ballast only, events added, growth attributed to `site_events`) — this is +`EstimateSiteEventsSize_TracksTheRealFootprint`, run on every build: + +| Workload | estimated | actual | error | +| --- | ---: | ---: | ---: | +| narrow rows, no details | 3 155 626 | 2 912 256 | **+8.4 %** | +| typical rows, 200 B details | 3 992 096 | 3 538 944 | **+12.8 %** | +| wide rows, 2 KB details | 12 748 048 | 12 845 056 | **−0.8 %** | + +The test asserts the band **−5 % … +25 %**. The bias is intentionally to the high side: a cap that +fires slightly early forfeits a slice of the budget, whereas one that reads low lets the log +overrun the disk allowance the cap exists to defend. Against the previous behaviour's **+250 %** +error on a replicated node this is not a close call. + +**Known limitation.** The model samples 1000 rows out of a table that may hold millions. An event +stream whose row width changes sharply *in the middle* of the history — neither at the head nor the +tail — is mis-sized until the trim reaches it. Self-correcting in practice, since the cap is +re-evaluated every tick and the head sample advances as the oldest rows go. + +## 4. The wipe-prevention guard, restated + +The register asked whether the "size did not decrease" guard should survive. It should, and it +does, but its meaning has changed and it has gained a sibling. There are now **two** backstops: + +1. **Unusable row width → refuse to trim.** Checked *before* the cap comparison, because a zero + bytes-per-row makes "is `site_events` over cap" unanswerable rather than false. Logs a Warning + naming the row count and deletes nothing. The old code had no analogue: its answer to an + unanswerable cap was to keep deleting until the file shrank, which is exactly how a cap that can + never be met empties a table. + +2. **Estimated size did not decrease across a batch → stop.** The old guard, re-based onto the + table-scoped metric. Crucially it **can no longer be tripped by replication bookkeeping** — the + metric excludes it — so when it fires it now means precisely one thing: the table is not + shrinking even though deletes are landing, i.e. **new events are arriving at least as fast as + the trim removes them.** That is a real operational condition and the Warning says so. + + For this to be observable rather than tautological, the loop re-reads the **row count** from the + database after each batch instead of decrementing a local counter, so concurrent recorder writes + are visible. Bytes-per-row, by contrast, is sampled **once per tick and held fixed** — re-sampling + every batch would make the estimate jitter as the trim consumes the head of the table, and a + sample that happened to widen could stall the loop through this very guard. That is the same + class of self-defeating measurement as row 81 itself, and it is deliberately avoided. + +Both backstops are covered by tests that pin a degenerate estimate through `internal virtual` +seams (`EstimateSiteEventsSize`, `GetSiteEventsRowCount`). + +## 5. Behaviour on an UNREPLICATED node + +Materially unchanged, as intended — but not bit-identical, and the delta is worth stating. + +On a node with no CDC triggers there is no oplog and no tombstone table, so whole-file logical size +was already ≈ `site_events` + the nine other (largely small) tables. The cap therefore used to fire +at roughly the right place, and the row-34 measurement confirms it: the unreplicated trim reached +66.98 MB against a 67.11 MB cap. + +What changes: + +- **Slightly more headroom.** The other nine tables no longer count against the event log's budget. + On a rig-shaped site those tables are small relative to a 1 GB event log, so the shift is a few + percent at most. +- **Model error replaces measurement error.** Where the old number was exact-but-wrong-scoped, the + new one is right-scoped but carries the +8 %/+13 % conservative bias of §3.1. Net effect on an + unreplicated node: the cap fires marginally earlier than before at the same setting. + +Neither warrants a config change. Sites that were happy with `MaxStorageMb: 1024` remain so. + +## 6. Explicitly out of scope: LocalDb's own bookkeeping + +This change makes the cap ignore `__localdb_oplog`, `__localdb_row_version` and +`__localdb_snapshot_state`. It does **not** attempt to manage them, and should not. + +Their size is governed by LocalDb's own machinery — `LocalDb:Replication:MaxOplogRows` (default +1 000 000) and `TombstoneRetention` (default 7 days) — and row 34's pacing +(`MaxPurgedRowsPerTick`) is what keeps a purge burst from blowing through the oplog cap and forcing +a snapshot resync. Those are the correct controls and they already exist. A second, competing +bound applied from the event log would only obscure which subsystem is responsible for a full disk. + +The honest statement of the budget is therefore: **`MaxStorageMb` bounds `site_events` and its +indexes; LocalDb replication bookkeeping is separate overhead on the same volume, bounded +separately.** Sizing a site's data volume means adding the two, and the topology guide now says so. +Row 34's measurement gives the scale — a 2.73 M-row purge left 707 MB of bookkeeping in the file +after deleting a 1 GB event log — and that overhead is transient, draining as the peer acks and as +tombstones expire. + +## 7. Verification + +- **`dbstat` unavailability probed before any implementation was written**, on a real file, with + the result recorded in §2 and pinned by `SqliteCapabilityTests`. +- **Fail-before, row 81.** With `EstimateSiteEventsSize` reverted to pre-row-81 semantics (whole + file attributed to `site_events`) and nothing else changed, **5 of the new tests fail** and all + 99 others pass. `PurgeByStorageCap_WithLargeBallastInTheSameFile_StillEnforces…` reproduces the + original signature exactly: `remaining=2000 estimate=21725184 cap=11534336` — 4000 of 6000 rows + destroyed and the cap **still unmet**. +- **Fail-before, row 84.** With per-phase emission restored, + `RunPurge_WhenBothPhasesDeleteRows_LogsTheBacklogNoteOnceForTheWholeTick` fails with + `Assert.Single() Failure: The collection contained 2 matching items`. +- `dotnet build ZB.MOM.WW.ScadaBridge.slnx` — clean, 0 warnings. +- `ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests`: **104 passed / 0 failed** (93 before this change). +- The docker rig was not touched. + +## 8. Register row 84, folded in + +`LogReplicationBacklogNote` was emitted by each purge phase, so a tick in which the retention purge +*and* the cap trim both deleted rows produced two identical Information notes. It is now emitted +once from `RunPurge`, driven by the tick's shared `PurgeBudget`. + +The budget is the natural source: it already holds exactly "rows this tick deleted", which is also +the more useful number to put next to an oplog spike — the tick's whole contribution rather than +one phase's share. `PurgeByRetention` keeps its own "Purged N events older than D days" line; only +the replication note moved. diff --git a/docs/requirements/Component-SiteEventLogging.md b/docs/requirements/Component-SiteEventLogging.md index 7a40c737..8c374e76 100644 --- a/docs/requirements/Component-SiteEventLogging.md +++ b/docs/requirements/Component-SiteEventLogging.md @@ -93,7 +93,50 @@ Each event entry contains: rig's site-b/site-c), the log stays node-local and a failover does start it fresh — the documented trade of not configuring a peer, unchanged by this policy. - **Retention**: 30 days. A **daily background job** runs on the active node and deletes all events older than 30 days. Hard delete — no archival. Deletes are sliced into bounded 1000-row batches per DELETE statement rather than one unbounded statement, so a large expired backlog does not hold the write lock (and every concurrent recorder flush) for the duration of the purge. -- **Storage cap**: A configurable maximum database size (default: 1 GB) is enforced. If the storage cap is reached before the 30-day retention window, the oldest events are purged first. This prevents disk exhaustion from alarm storms, script failure loops, or connection flapping. +- **Storage cap**: A configurable maximum size (default: 1 GB) is enforced. If the cap is reached + before the 30-day retention window, the oldest events are purged first. This prevents disk + exhaustion from alarm storms, script failure loops, or connection flapping. +- **The cap measures `site_events` and its four indexes — NOT the database file** (register row 81; + decision record `docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md`). This matters + because the event log shares one SQLite file with nine other tables plus LocalDb's + `__localdb_oplog` / `__localdb_row_version` / `__localdb_snapshot_state` bookkeeping. The cap used + to compare `MaxStorageMb` against `page_count − freelist_count` over that whole file, which on a + replication-enabled node made the trim **unwinnable**: each 1000-row delete freed ~390 KB of event + pages while adding ~1000 oplog rows and ~1000 tombstones to the same file, the measured size did + not fall, and the progress guard stopped the trim — measured 2.5x over a 64 MB cap with 226 k rows + still present. A node whose peer was down could not enforce its cap at all. Two consequences of + the new scoping are worth internalising: + - **The cap is now independent of replication health.** It was previously a function of the + *peer's* liveness, and in the wrong direction — an inflated oplog is a replication fault, and + letting it drive event deletion would destroy operational history in response to one. + - **`MaxStorageMb` no longer bounds the data volume on its own.** LocalDb bookkeeping is separate + overhead on the same disk, bounded separately by `LocalDb:Replication:MaxOplogRows` and + `TombstoneRetention`; sizing a site's volume means adding the two. Managing that bookkeeping is + deliberately **not** this component's job — see the decision record §6. +- **The measurement is modelled, not exact.** SQLite can report per-table page usage precisely via + the `dbstat` virtual table, and that was the intended fix — but `dbstat` is a compile-time option + and the bundled `SQLitePCLRaw.lib.e_sqlite3` native library (SQLite 3.53.3) does **not** enable it; + neither `dbstat` nor `sqlite_dbpage` exists, verified by probe and pinned by + `SqliteCapabilityTests`. The table's footprint is therefore estimated from sampled row width + (500 rows from each end of the table, measured with `octet_length` so multi-byte UTF-8 is not + under-counted) fed into a page-layout model; index pages count against the cap, deliberately, + because they are ~34 % of the table's real footprint and the 1 GB default was sized against a + bytes/row figure that included them. Measured error is **−0.8 % to +12.8 %** across representative + workloads, biased high on purpose — a cap that fires slightly early forfeits budget, whereas one + that reads low fails at the only job it has. The estimate is additionally clamped by the + whole-file logical size, which is a true upper bound on any one table. +- **Two wipe-prevention backstops** guard the cap trim, replacing the single "on-disk size did not + decrease" check. (1) If row width cannot be sampled, the trim **refuses to run** and warns — + checked before the cap comparison, because a zero row width makes "are we over cap" unanswerable + rather than false, and the old loop's answer to an unanswerable cap was to keep deleting. (2) If + the *estimated table size* fails to fall across a batch, the trim stops and warns. Guard (2) is the + old check re-based onto the table-scoped metric, and its meaning is now unambiguous: replication + bookkeeping can no longer trip it, so it fires only when new events are arriving at least as fast + as the trim removes them. For that to be observable, the loop re-reads the row count from the + database after every batch, while bytes-per-row is sampled **once per tick and held fixed** — + re-sampling per batch would make the estimate jitter as the trim eats the head of the table and + could stall the loop through guard (2), which is the same self-defeating-measurement failure as + row 81 itself. - **Per-tick delete ceiling** (`MaxPurgedRowsPerTick`, default **250 000**; `0` = unlimited): one purge tick deletes at most this many rows, **shared** by the retention purge and the storage-cap trim — two independently-capped phases would let a tick emit twice the intended burst. A tick that @@ -128,7 +171,10 @@ Each event entry contains: replication fault and not the purge. The purge logs an Information line naming the row count and the expected transient backlog whenever it deletes rows on a replication-enabled node, so an operator can correlate a spike with the purge that caused it — a spike with no such line nearby is - not the purge. Node-local wiring: the Host supplies the replication predicate + not the purge. That line is emitted **once per tick**, carrying the retention purge's and the cap + trim's deletes combined (register row 84 — it used to fire once per phase, so a tick in which both + deleted produced two identical notes; the tick total is also the more useful number to put beside + an oplog spike). Node-local wiring: the Host supplies the replication predicate (`SiteLocalDbSetup.ReplicationIsConfigured` — the `PeerAddress`-OR-`ApiKey` rule) as `SiteEventLogReplicationCheck`; this component never reads LocalDb configuration itself, and with no predicate registered the note is suppressed. Operator detail — diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/EventLogPurgeService.cs b/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/EventLogPurgeService.cs index fad27c36..3055c5df 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/EventLogPurgeService.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/EventLogPurgeService.cs @@ -1,3 +1,5 @@ +using System.Globalization; +using Microsoft.Data.Sqlite; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; @@ -60,6 +62,40 @@ public class EventLogPurgeService : BackgroundService /// Number of events deleted per retention-purge batch — same size as . private const int RetentionPurgeBatchSize = 1000; + /// + /// Rows sampled from each end of site_events when sizing an average row. See + /// . + /// + private const int SizeSampleRows = 500; + + /// + /// Per-row bookkeeping a table B-tree leaf spends on top of the row's own bytes: the + /// payload-length varint, the rowid varint and the 2-byte cell-pointer slot. + /// + private const int TableCellOverheadBytes = 16; + + /// + /// Bytes at the end of a page SQLite will not fill with local payload — the + /// pageSize - 35 maximum-local-payload rule for table leaves. + /// + private const int PageReservedBytes = 35; + + /// + /// Average proportion of a table leaf page that actually holds rows. B-tree splits leave + /// pages part-empty; 0.78 is the measured mean across the workloads in + /// docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md §3. + /// + private const double TablePageFillFactor = 0.78; + + /// Number of indexes on site_events (timestamp, event_type, instance_id, severity). + private const int IndexedColumnCount = 4; + + /// Per-entry bookkeeping in an index B-tree leaf: key-length varint, rowid and cell pointer. + private const int IndexEntryOverheadBytes = 8; + + /// Average fill of an index leaf page; measured alongside . + private const double IndexPageFillFactor = 0.75; + /// Minimum spacing between ceiling-reached log lines; see . private static readonly TimeSpan CeilingLogInterval = TimeSpan.FromMinutes(15); @@ -186,6 +222,14 @@ public class EventLogPurgeService : BackgroundService PurgeByRetention(budget); PurgeByStorageCap(budget); + // Register row 84: emitted ONCE per tick, from the tick's shared budget, rather + // than once per phase. A tick in which both the retention purge and the cap trim + // deleted rows used to log two identical Information notes; the number an operator + // wants next to the oplog spike is the tick total anyway, which is exactly what + // the shared budget already holds. + if (budget.Deleted > 0) + LogReplicationBacklogNote(budget.Deleted); + if (!budget.StoppedAtCeiling) return false; @@ -290,10 +334,7 @@ public class EventLogPurgeService : BackgroundService } if (totalDeleted > 0) - { _logger.LogInformation("Purged {Count} events older than {Days} days", totalDeleted, _options.RetentionDays); - LogReplicationBacklogNote(totalDeleted); - } } /// @@ -318,9 +359,17 @@ public class EventLogPurgeService : BackgroundService /// /// Emits the operator breadcrumb that explains the oplog backlog spike a purge produces on a - /// replication-enabled node. No-op when this node has no replication peer. + /// replication-enabled node — once per purge tick. No-op when this node has no + /// replication peer. /// /// + /// + /// Called from rather than from each phase (register row 84). Both the + /// retention purge and the cap trim generate the same CDC cost, and a tick in which both + /// deleted rows used to emit two identical Information notes. One note carrying the tick's + /// combined total is what an operator correlating an oplog spike actually wants. + /// + /// /// site_events is a replicated table, and a retention/cap DELETE is captured by CDC /// exactly like an ordinary write — there is deliberately no purge-exemption path (LocalDb /// Phase 2: CDC does all three jobs). The daily purge therefore pushes one oplog row per @@ -329,8 +378,12 @@ public class EventLogPurgeService : BackgroundService /// on its own; without this line an operator correlating the spike has nothing in the log to /// tie it to. Information level because it is only interesting next to the purge line it /// follows — the spike itself is not a fault. + /// /// - /// Number of rows the purge just deleted; always > 0 at the call sites. + /// + /// Rows deleted by the WHOLE tick — retention purge and cap trim combined, read off the + /// shared . Always > 0 at the single call site. + /// private void LogReplicationBacklogNote(int deletedRows) { bool replicated; @@ -358,13 +411,52 @@ public class EventLogPurgeService : BackgroundService _options.MaxPurgedRowsPerTick > 0 ? _options.MaxPurgedRowsPerTick.ToString() : "unlimited"); } + /// + /// Trims the oldest events until site_events' own footprint is back under + /// . + /// + /// + /// + /// The cap is table-scoped as of register row 81. It used to compare + /// against the whole consolidated LocalDb + /// file, which on a replication-enabled node made the trim unwinnable: every batch freed + /// event pages and added an equal number of oplog rows and row-version tombstones to the + /// same file, so the measured size did not fall and the progress guard stopped the trim + /// 2.5x over cap with 226 k rows still present. The cap now measures + /// — site_events and its four indexes only — + /// so replication bookkeeping can no longer consume, or block, the event log's budget. + /// + /// + /// Bytes-per-row is sampled ONCE per tick and held fixed for the whole loop, while the row + /// count is re-read after each batch. That split is deliberate: re-sampling row width every + /// batch would make the estimate jitter as the trim consumes the head of the table, and a + /// sample that happened to widen could stall the loop through the progress guard below — + /// the same class of self-defeating measurement row 81 was about. + /// + /// /// The tick's shared delete budget, already drawn down by the retention purge. private void PurgeByStorageCap(PurgeBudget budget) { var capBytes = (long)_options.MaxStorageMb * 1024 * 1024; - var currentSizeBytes = GetDatabaseSizeBytes(); + var estimate = EstimateSiteEventsSize(); - if (currentSizeBytes <= capBytes) + if (estimate.RowCount <= 0) + return; + + // Wipe-prevention backstop, first of two — checked BEFORE the cap comparison, because a + // zero row width makes "site_events is over cap" unanswerable rather than false. An + // unusable width (empty sample, degenerate estimate) used to have no analogue: the old + // loop's answer to an unanswerable cap was to keep deleting. Refuse instead. + if (estimate.BytesPerRow <= 0) + { + _logger.LogWarning( + "Storage-cap trim skipped: site_events row width could not be sampled ({Rows} rows). " + + "No rows are deleted rather than trimming against an unusable size estimate.", + estimate.RowCount); + return; + } + + if (estimate.EstimatedBytes <= capBytes) return; // Over cap but out of budget: flag the catch-up tick and stay silent rather than logging @@ -378,14 +470,18 @@ public class EventLogPurgeService : BackgroundService } _logger.LogWarning( - "Event log size {Size:F1} MB exceeds cap {Cap} MB — purging oldest events", - currentSizeBytes / (1024.0 * 1024.0), _options.MaxStorageMb); + "site_events occupies about {Size:F1} MB across {Rows} rows — over the {Cap} MB cap. " + + "Trimming the oldest events. (The cap measures the event table and its indexes only, " + + "not the whole consolidated LocalDb file.)", + estimate.EstimatedBytes / (1024.0 * 1024.0), estimate.RowCount, _options.MaxStorageMb); - // Delete the oldest events in batches until the database is under the cap. - // The loop also stops if the on-disk size fails to decrease across an - // iteration (e.g. if vacuum cannot reclaim space), so a cap that can never - // be met does not silently empty the entire table. + // Delete the oldest events in batches until the ESTIMATED TABLE size is under the cap. + // Wipe-prevention backstop, second of two: the loop also stops if the estimate fails to + // fall across an iteration. Replication bookkeeping can no longer trip that — the metric + // excludes it — so it now means what it says: the table is not shrinking, because a batch + // deleted nothing or because concurrent recorder writes are outrunning the trim. var totalDeleted = 0; + var currentSizeBytes = estimate.EstimatedBytes; while (currentSizeBytes > capBytes) { @@ -430,57 +526,213 @@ public class EventLogPurgeService : BackgroundService totalDeleted += deleted; budget.Record(deleted); - currentSizeBytes = GetDatabaseSizeBytes(); + + // Row count re-read from the database, not decremented locally, so concurrent + // recorder writes are visible; row width stays fixed for the tick (see remarks). + currentSizeBytes = (long)(GetSiteEventsRowCount() * estimate.BytesPerRow); if (currentSizeBytes >= previousSizeBytes) { - // Size is not shrinking despite deletes — stop rather than wipe the - // whole table. This should not happen now that logical size is - // measured, but guards against any future regression. _logger.LogWarning( - "Event log size did not decrease after a cap-purge batch ({Size:F1} MB); " + - "stopping to avoid emptying the log", + "Estimated site_events size did not decrease after a cap-purge batch " + + "({Size:F1} MB); stopping to avoid emptying the log. Deletes are landing, so " + + "this means new events are arriving at least as fast as the trim removes them.", currentSizeBytes / (1024.0 * 1024.0)); break; } } - - // Same CDC cost as the retention purge above — a cap-driven trim is usually the - // larger of the two, so it gets the same operator breadcrumb. - if (totalDeleted > 0) - { - LogReplicationBacklogNote(totalDeleted); - } } /// - /// Returns the logical size of the database in bytes — only pages that hold live - /// data, excluding free pages on the freelist. Measuring logical size (rather than - /// the raw file size from page_count) means the storage-cap loop observes - /// space being reclaimed even if free pages have not yet been returned to the OS. + /// Returns the logical size of the WHOLE consolidated database file in bytes — only pages + /// that hold live data, excluding free pages on the freelist. /// - /// The logical database size in bytes (used pages × page size). + /// + /// + /// This is no longer what the storage cap measures (register row 81, + /// docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md). Since LocalDb + /// Phase 1/2 the file holds ten tables plus __localdb_oplog, + /// __localdb_row_version and __localdb_snapshot_state, so a whole-file + /// number is not site_events' size: on a replication-enabled node each cap-trim + /// batch freed ~390 KB of event pages while adding ~1000 oplog rows and ~1000 tombstones + /// to the same file, and the trim fought itself to a standstill 2.5x over cap. + /// + /// + /// It survives for two narrow jobs: it is a true UPPER BOUND on site_events' own + /// pages, which uses to clamp an over-eager model, + /// and it remains a useful diagnostic for the file as a whole. + /// + /// + /// The logical size of the whole database file in bytes (used pages × page size). internal long GetDatabaseSizeBytes() + { + return _eventLogger.WithConnection(connection => ReadLogicalFileBytes(connection)); + } + + /// Logical size of the whole file, on an already-held connection. + /// An open connection to the consolidated database. + /// Used pages × page size, in bytes. + private static long ReadLogicalFileBytes(SqliteConnection connection) + { + var pageCount = ReadPragmaLong(connection, "PRAGMA page_count"); + var freeListCount = ReadPragmaLong(connection, "PRAGMA freelist_count"); + var pageSize = ReadPragmaLong(connection, "PRAGMA page_size"); + return Math.Max(0, pageCount - freeListCount) * pageSize; + } + + /// Reads a single-value PRAGMA as a 64-bit integer. + /// An open connection. + /// The PRAGMA statement to run. + /// The PRAGMA's value. + private static long ReadPragmaLong(SqliteConnection connection, string pragma) + { + using var cmd = connection.CreateCommand(); + cmd.CommandText = pragma; + return Convert.ToInt64(cmd.ExecuteScalar(), CultureInfo.InvariantCulture); + } + + /// + /// How many rows site_events currently holds, and how many bytes of the file one + /// average row occupies — the two numbers the storage cap is expressed in. + /// + /// Live row count at the time of the estimate. + /// + /// Modelled file bytes per row, table pages plus index pages. 0 when the table is + /// empty or the sample could not be sized, which the cap trim treats as "do not trim". + /// + internal readonly record struct SiteEventsSizeEstimate(long RowCount, double BytesPerRow) + { + /// Modelled total bytes site_events occupies in the file. + public long EstimatedBytes => (long)(RowCount * BytesPerRow); + } + + /// + /// Estimates how much of the consolidated file site_events — and only + /// site_events — occupies, by sampling average row width and modelling SQLite's + /// page layout. + /// + /// + /// + /// Why a model and not a measurement. SQLite can report per-table page usage + /// exactly through the dbstat virtual table, and that was the intended fix for + /// register row 81 — but dbstat is a compile-time option and the + /// SQLitePCLRaw.lib.e_sqlite3 native build this solution ships does NOT enable it. + /// Probed directly (SqliteCapabilityTests): PRAGMA compile_options on + /// SQLite 3.53.3 lists no ENABLE_DBSTAT_VTAB, pragma_module_list returns ten + /// modules (fts3/4/5, rtree, geopoly) with neither dbstat nor sqlite_dbpage + /// among them, and selecting from dbstat fails with "no such table". So an exact + /// per-table page count is not obtainable from this provider at all, and the cap is + /// modelled instead. That trade is recorded in + /// docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md. + /// + /// + /// The model. Rows are sampled from both ends of the table ( + /// from each — the head is what the oldest-first trim will actually delete, the tail catches a + /// workload whose event shape has drifted) to get an average payload width and an average + /// width across the four indexed columns. Table cost is then computed as whole pages — + /// ceil(rows / rowsPerPage) × pageSize — rather than as a flat bytes-per-row rate, + /// because that is the term that dominates once rows approach half a page: rows too wide to + /// pack two-per-page waste the remainder, which a linear model underestimates by ~40 %. + /// Index cost is added per row from the sampled indexed-column widths, so an event stream + /// that leaves instance_id null is charged less than one that fills it. + /// + /// + /// Index pages count against the cap — deliberately. The four indexes are storage the + /// event log causes and owns (measured at ~34 % of the table's total footprint), and the + /// 1 GB default was sized against the 393 bytes/row figure that already included them. + /// Excluding them would silently raise real disk use by about a third at the same setting. + /// + /// + /// Clamped by the file. The whole-file logical size is a true upper bound on any one + /// table's pages, so the model is capped by it. That can only ever correct an + /// over-estimate downward; it cannot reintroduce the row-81 defect, because on a replicated + /// node the file is larger than site_events, not smaller, and so never binds. + /// + /// + /// Marked virtual so tests can substitute a degenerate estimate and exercise the + /// trim's backstops. + /// + /// + /// The current row count and modelled bytes per row. + internal virtual SiteEventsSizeEstimate EstimateSiteEventsSize() { return _eventLogger.WithConnection(connection => { - using var pageCountCmd = connection.CreateCommand(); - pageCountCmd.CommandText = "PRAGMA page_count"; - var pageCount = (long)pageCountCmd.ExecuteScalar()!; + var rowCount = ReadPragmaLong(connection, "SELECT COUNT(*) FROM site_events"); + if (rowCount <= 0) + return new SiteEventsSizeEstimate(0, 0); - using var freeListCmd = connection.CreateCommand(); - freeListCmd.CommandText = "PRAGMA freelist_count"; - var freeListCount = (long)freeListCmd.ExecuteScalar()!; + double avgPayloadBytes; + double avgIndexedBytes; + using (var sampleCmd = connection.CreateCommand()) + { + // octet_length (SQLite 3.43+) rather than length(), which counts CHARACTERS: + // a message with multi-byte UTF-8 would otherwise be under-sized. Pinned by + // SqliteCapabilityTests so a provider downgrade fails a test rather than + // silently shrinking every estimate. + sampleCmd.CommandText = $""" + SELECT AVG(payload_bytes), AVG(indexed_bytes) FROM ( + SELECT payload_bytes, indexed_bytes FROM ( + SELECT + octet_length(id) + octet_length(timestamp) + octet_length(event_type) + + octet_length(severity) + COALESCE(octet_length(instance_id), 0) + + octet_length(source) + octet_length(message) + + COALESCE(octet_length(details), 0) AS payload_bytes, + octet_length(timestamp) + octet_length(event_type) + + octet_length(severity) + COALESCE(octet_length(instance_id), 0) + AS indexed_bytes + FROM site_events LIMIT {SizeSampleRows} + ) + UNION ALL + SELECT payload_bytes, indexed_bytes FROM ( + SELECT + octet_length(id) + octet_length(timestamp) + octet_length(event_type) + + octet_length(severity) + COALESCE(octet_length(instance_id), 0) + + octet_length(source) + octet_length(message) + + COALESCE(octet_length(details), 0) AS payload_bytes, + octet_length(timestamp) + octet_length(event_type) + + octet_length(severity) + COALESCE(octet_length(instance_id), 0) + AS indexed_bytes + FROM site_events ORDER BY rowid DESC LIMIT {SizeSampleRows} + ) + ) + """; + using var reader = sampleCmd.ExecuteReader(); + if (!reader.Read() || reader.IsDBNull(0)) + return new SiteEventsSizeEstimate(rowCount, 0); - using var pageSizeCmd = connection.CreateCommand(); - pageSizeCmd.CommandText = "PRAGMA page_size"; - var pageSize = (long)pageSizeCmd.ExecuteScalar()!; + avgPayloadBytes = reader.GetDouble(0); + avgIndexedBytes = reader.IsDBNull(1) ? 0 : reader.GetDouble(1); + } - var usedPages = Math.Max(0, pageCount - freeListCount); - return usedPages * pageSize; + var pageSize = ReadPragmaLong(connection, "PRAGMA page_size"); + var usablePerPage = (pageSize - PageReservedBytes) * TablePageFillFactor; + var avgCellBytes = avgPayloadBytes + TableCellOverheadBytes; + + // At least one row per page: a row wider than a page spills to overflow pages, + // which this floor charges as a whole page each — close enough, and never under. + var rowsPerPage = Math.Max(1, (long)(usablePerPage / Math.Max(1, avgCellBytes))); + var tableBytes = (long)Math.Ceiling(rowCount / (double)rowsPerPage) * pageSize; + + var indexBytesPerRow = + (avgIndexedBytes + (IndexEntryOverheadBytes * IndexedColumnCount)) / IndexPageFillFactor; + + var modelled = tableBytes + (long)(rowCount * indexBytesPerRow); + var clamped = Math.Min(modelled, ReadLogicalFileBytes(connection)); + + return new SiteEventsSizeEstimate(rowCount, clamped / (double)rowCount); }); } + /// Live site_events row count. + /// + /// Re-read after every cap-trim batch so the trim's progress check sees concurrent + /// recorder writes, not just its own deletes. virtual for the backstop tests. + /// + /// Number of rows currently in site_events. + internal virtual long GetSiteEventsRowCount() => + _eventLogger.WithConnection(connection => ReadPragmaLong(connection, "SELECT COUNT(*) FROM site_events")); + /// /// One purge tick's shared delete allowance, drawn down by the retention purge and then the /// storage-cap trim. diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogOptions.cs b/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogOptions.cs index 00c19ce9..1feeee3e 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogOptions.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteEventLogging/SiteEventLogOptions.cs @@ -4,7 +4,34 @@ public class SiteEventLogOptions { /// Number of days to retain site event log entries before purge; default 30. public int RetentionDays { get; set; } = 30; - /// Maximum SQLite database size in megabytes before old entries are purged; default 1024 MB. + /// + /// Maximum size in megabytes of site_events AND ITS FOUR INDEXES before the oldest + /// entries are trimmed; default 1024 MB. + /// + /// + /// + /// This is not a cap on the database file (register row 81, decision record + /// docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md). site_events + /// shares one SQLite file at LocalDb:Path with nine other tables plus LocalDb's + /// __localdb_oplog / __localdb_row_version bookkeeping. Measuring the whole file + /// made the trim unwinnable on a replication-enabled node — each batch of deletes generated + /// an equal number of oplog rows and tombstones in the same file, so the measured size never + /// fell and the trim stopped 2.5x over cap. Worse, it made the event log's budget a function + /// of the replication peer's health, in the direction where a replication fault destroys + /// operational history. + /// + /// + /// Consequence for sizing a site's data volume: this value alone does not bound it. LocalDb + /// replication bookkeeping is separate overhead on the same disk, bounded by + /// LocalDb:Replication:MaxOplogRows and TombstoneRetention. Budget the sum. + /// + /// + /// The footprint is MODELLED from sampled row width rather than measured exactly: SQLite's + /// dbstat virtual table would give an exact per-table page count but is not compiled + /// into the bundled native library. Measured accuracy is −0.8 % to +12.8 %, deliberately + /// biased high. See EventLogPurgeService.EstimateSiteEventsSize. + /// + /// public int MaxStorageMb { get; set; } = 1024; /// /// MIGRATION-ONLY as of LocalDb Phase 1. no longer reads diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogPurgeServiceTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogPurgeServiceTests.cs index a26f7cdd..3d92bfa9 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogPurgeServiceTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogPurgeServiceTests.cs @@ -547,6 +547,47 @@ public class EventLogPurgeServiceTests : IDisposable Assert.Equal(LogLevel.Information, note.Level); } + [Fact] + public void RunPurge_WhenBothPhasesDeleteRows_LogsTheBacklogNoteOnceForTheWholeTick() + { + // Register row 84. The note used to be emitted by each phase, so a tick in which the + // retention purge AND the cap trim both deleted rows produced two identical Information + // lines. It is now emitted once, from the tick's shared delete budget — which also makes + // the number it reports the figure an operator actually wants next to an oplog spike: + // the whole tick's contribution, not one phase's. + const int expiredRows = 50; + const int recentRows = 50; + for (int i = 0; i < expiredRows; i++) + { + InsertEventWithTimestamp(DateTimeOffset.UtcNow.AddDays(-31)); + } + for (int i = 0; i < recentRows; i++) + { + InsertEventWithTimestamp(DateTimeOffset.UtcNow); + } + + var capOptions = new SiteEventLogOptions + { + DatabasePath = _dbPath, + RetentionDays = 30, + MaxStorageMb = 0 // retention takes the expired rows; the cap trim takes the rest + }; + + var logger = new CapturingLogger(); + var purge = CreatePurgeService(capOptions, isReplicationConfigured: () => true, logger: logger); + purge.RunPurge(); + + // Both phases really did delete — otherwise this would pass for the wrong reason. + Assert.Contains(logger.Entries, e => + e.Message.Contains($"Purged {expiredRows} events older than", StringComparison.Ordinal)); + Assert.Contains(logger.Entries, e => e.Message.Contains("over the 0 MB cap", StringComparison.Ordinal)); + Assert.Equal(0, GetEventCount()); + + var note = Assert.Single(logger.Entries, e => e.Message.Contains(BacklogNoteFragment, StringComparison.Ordinal)); + Assert.Equal(LogLevel.Information, note.Level); + Assert.Contains($"Purged {expiredRows + recentRows} site_events rows", note.Message, StringComparison.Ordinal); + } + [Fact] public void RunPurge_WhenReplicationCheckThrows_StillPurgesAndSwallows() { diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogStorageCapScopeTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogStorageCapScopeTests.cs new file mode 100644 index 00000000..308be8d3 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/EventLogStorageCapScopeTests.cs @@ -0,0 +1,365 @@ +using Microsoft.Data.Sqlite; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; +using Xunit.Abstractions; + +namespace ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests; + +/// +/// Register row 81 — the storage cap measures site_events' own pages, not the whole +/// consolidated LocalDb file. +/// +/// +/// +/// The defect these tests close: site_events shares one SQLite file with nine other +/// tables plus LocalDb's __localdb_oplog / __localdb_row_version bookkeeping, and +/// the cap used to compare MaxStorageMb against page_count - freelist_count over +/// that whole file. On a replication-enabled node the trim therefore fought itself — each +/// 1000-row delete freed ~390 KB of event pages while adding ~1000 oplog rows and ~1000 +/// tombstones to the same file — and stopped 2.5x over a 64 MB cap with 226 k rows still +/// present (docs/plans/2026-08-15-site-events-purge-burst-measurement.md §5). +/// +/// +/// A real replication pair is not needed to pin the semantics: what matters is that OTHER pages +/// in the same file neither consume nor block the event log's budget. A plain ballast table +/// stands in for the oplog, tombstones and the other nine tables alike. +/// +/// +public class EventLogStorageCapScopeTests : IDisposable +{ + private readonly ITestOutputHelper _output; + private readonly SiteEventLogger _eventLogger; + private readonly TestLocalDb _localDb; + private readonly string _dbPath; + + public EventLogStorageCapScopeTests(ITestOutputHelper output) + { + _output = output; + _dbPath = Path.Combine(Path.GetTempPath(), $"test_capscope_{Guid.NewGuid()}.db"); + _localDb = TestLocalDb.Create(_dbPath); + _eventLogger = new SiteEventLogger( + Options.Create(new SiteEventLogOptions { DatabasePath = _dbPath }), + NullLogger.Instance, + _localDb.Db); + } + + public void Dispose() + { + _eventLogger.Dispose(); + _localDb.Dispose(); + TestLocalDb.DeleteFiles(_dbPath); + GC.SuppressFinalize(this); + } + + private EventLogPurgeService CreatePurgeService(SiteEventLogOptions options, ILogger? logger = null) => + new(_eventLogger, Options.Create(options), logger ?? NullLogger.Instance); + + private SiteEventLogOptions CapOptions(int maxStorageMb) => new() + { + DatabasePath = _dbPath, + // Far enough in the past that the retention purge never fires — these tests are about + // the cap trim in isolation, and a shared tick budget would otherwise blur the two. + RetentionDays = 3650, + MaxStorageMb = maxStorageMb, + }; + + /// Seeds events, each ~256 bytes of payload. + private void SeedEvents(int count) + { + var details = new string('x', 200); + _eventLogger.WithConnection(connection => + { + using var tx = connection.BeginTransaction(); + using var cmd = connection.CreateCommand(); + cmd.Transaction = tx; + cmd.CommandText = """ + INSERT INTO site_events (id, timestamp, event_type, severity, instance_id, source, message, details) + VALUES ($id, $ts, 'script', 'Info', $inst, 'SiteRuntime', 'Bulk event', $details) + """; + var id = cmd.Parameters.Add("$id", SqliteType.Text); + var ts = cmd.Parameters.Add("$ts", SqliteType.Text); + var inst = cmd.Parameters.Add("$inst", SqliteType.Text); + var det = cmd.Parameters.Add("$details", SqliteType.Text); + var start = new DateTimeOffset(2026, 1, 1, 0, 0, 0, TimeSpan.Zero); + for (var i = 0; i < count; i++) + { + id.Value = Guid.NewGuid().ToString("N"); + ts.Value = start.AddSeconds(i).ToString("o"); + inst.Value = i % 3 == 0 ? DBNull.Value : Guid.NewGuid().ToString(); + det.Value = details; + cmd.ExecuteNonQuery(); + } + tx.Commit(); + }); + } + + /// + /// Fills a non-event table in the SAME file, standing in for LocalDb's oplog and + /// row-version tables and the nine other consolidated tables. + /// + private void SeedBallast(int rows, int bytesPerRow) + { + var payload = new string('b', bytesPerRow); + _eventLogger.WithConnection(connection => + { + using var create = connection.CreateCommand(); + create.CommandText = "CREATE TABLE IF NOT EXISTS test_ballast (seq INTEGER PRIMARY KEY, row_json TEXT)"; + create.ExecuteNonQuery(); + + using var tx = connection.BeginTransaction(); + using var cmd = connection.CreateCommand(); + cmd.Transaction = tx; + cmd.CommandText = "INSERT INTO test_ballast (row_json) VALUES ($p)"; + var p = cmd.Parameters.Add("$p", SqliteType.Text); + for (var i = 0; i < rows; i++) + { + p.Value = payload; + cmd.ExecuteNonQuery(); + } + tx.Commit(); + }); + } + + private long EventCount() => _eventLogger.WithConnection(connection => + { + using var cmd = connection.CreateCommand(); + cmd.CommandText = "SELECT COUNT(*) FROM site_events"; + return (long)cmd.ExecuteScalar()!; + }); + + [Fact] + public void EstimatedSize_ExcludesOtherTablesInTheSameFile() + { + // A small ballast is seeded up front so the whole-file clamp inside the estimator is + // slack in BOTH readings — otherwise the first would be pinned to the file size and the + // comparison would be measuring the clamp rather than the model. + SeedBallast(rows: 4_000, bytesPerRow: 400); + SeedEvents(4000); + + var purge = CreatePurgeService(CapOptions(1024)); + var eventsOnly = purge.EstimateSiteEventsSize().EstimatedBytes; + var fileBefore = purge.GetDatabaseSizeBytes(); + + SeedBallast(rows: 40_000, bytesPerRow: 500); + + var eventsAfterBallast = purge.EstimateSiteEventsSize().EstimatedBytes; + var fileAfter = purge.GetDatabaseSizeBytes(); + + _output.WriteLine($"site_events estimate {eventsOnly} -> {eventsAfterBallast}; file {fileBefore} -> {fileAfter}"); + + // The file grew several-fold; the event log's own measured footprint did not move at all. + Assert.True(fileAfter > fileBefore * 2, + $"Ballast must visibly grow the file ({fileBefore} -> {fileAfter})."); + Assert.Equal(eventsOnly, eventsAfterBallast); + } + + [Fact] + public void PurgeByStorageCap_WithLargeBallastInTheSameFile_DoesNotTrimAnUnderCapEventLog() + { + // The most direct expression of row 81: on a replicated node with an undrained oplog the + // file dwarfs site_events. Under the old whole-file cap the trim would run — and delete + // events — purely because of bytes the event log does not own. + SeedEvents(4000); + + var sizingProbe = CreatePurgeService(CapOptions(1024)); + var eventBytes = sizingProbe.EstimateSiteEventsSize().EstimatedBytes; + + SeedBallast(rows: 40_000, bytesPerRow: 500); + + // Cap comfortably above site_events but far BELOW the whole file. + var capMb = (int)Math.Max(1, (eventBytes * 2) / (1024 * 1024)); + var purge = CreatePurgeService(CapOptions(capMb)); + + Assert.True(purge.GetDatabaseSizeBytes() > (long)capMb * 1024 * 1024, + "Precondition: the whole file must exceed the cap, so a file-scoped cap would trim."); + + purge.RunPurge(); + + Assert.Equal(4000, EventCount()); + } + + [Fact] + public void PurgeByStorageCap_WithLargeBallastInTheSameFile_StillEnforcesTheCapOnEventsAndDoesNotEmptyTheTable() + { + // The other half: the cap must still be MET. Under the old whole-file measurement this + // was impossible with unreclaimable ballast present — the trim either emptied the table + // chasing a file size it could not reach, or (as measured) tripped the progress guard + // and left the log 2.5x over cap. + SeedEvents(6000); + SeedBallast(rows: 40_000, bytesPerRow: 500); + + var sizingProbe = CreatePurgeService(CapOptions(1024)); + var eventBytes = sizingProbe.EstimateSiteEventsSize().EstimatedBytes; + + var capBytes = eventBytes / 2; + var capMb = (int)Math.Max(1, capBytes / (1024 * 1024)); + var purge = CreatePurgeService(CapOptions(capMb)); + + purge.RunPurge(); + + var remaining = EventCount(); + var finalEstimate = purge.EstimateSiteEventsSize().EstimatedBytes; + var finalCapBytes = (long)capMb * 1024 * 1024; + + _output.WriteLine($"remaining={remaining} estimate={finalEstimate} cap={finalCapBytes} file={purge.GetDatabaseSizeBytes()}"); + + Assert.True(remaining > 0, "The cap trim must not empty the event table."); + Assert.True(remaining < 6000, "The cap trim must remove events when the event log is over cap."); + Assert.True(finalEstimate <= finalCapBytes, + $"site_events estimate {finalEstimate} must be at or below the cap {finalCapBytes}."); + + // And the proof that the cap is table-scoped: the FILE is still way over it, and that is + // correct — those bytes belong to LocalDb bookkeeping and the other consolidated tables. + Assert.True(purge.GetDatabaseSizeBytes() > finalCapBytes, + "The whole file is expected to stay over the cap — the cap no longer measures it."); + } + + // ── size-model accuracy ── + + public static TheoryData Workloads => new() + { + // name, rows, details length (0 = no details column), details on every row + { "narrow rows, no details", 8000, 0, 1.0 }, + { "typical rows, 200B details", 6000, 200, 1.0 }, + { "wide rows, 2KB details", 3000, 2048, 1.0 }, + }; + + [Theory] + [MemberData(nameof(Workloads))] + public void EstimateSiteEventsSize_TracksTheRealFootprint(string name, int rows, int detailsLength, double detailsFraction) + { + // Calibration guard for the modelled estimate. site_events' true page count is obtained + // DIFFERENTIALLY: the file is measured with ballast only, the events are then added, and + // the growth is what the table and its four indexes actually cost. Seeding the ballast + // first also keeps the estimator's whole-file clamp slack, so this scores the model + // itself rather than the clamp. + // + // The band is deliberately asymmetric. The model is tuned to run somewhat high, because + // a cap that fires early wastes a slice of the budget whereas one that reads low lets + // the log overrun the disk allowance the cap exists to defend. + SeedBallast(rows: 4_000, bytesPerRow: 400); + + var purge = CreatePurgeService(CapOptions(1024)); + var baselineBytes = purge.GetDatabaseSizeBytes(); + + var details = detailsLength > 0 ? new string('d', detailsLength) : null; + _eventLogger.WithConnection(connection => + { + using var tx = connection.BeginTransaction(); + using var cmd = connection.CreateCommand(); + cmd.Transaction = tx; + cmd.CommandText = """ + INSERT INTO site_events (id, timestamp, event_type, severity, instance_id, source, message, details) + VALUES ($id, $ts, 'ScriptExecution', 'Information', $inst, 'SiteRuntime', $msg, $details) + """; + var id = cmd.Parameters.Add("$id", SqliteType.Text); + var ts = cmd.Parameters.Add("$ts", SqliteType.Text); + var inst = cmd.Parameters.Add("$inst", SqliteType.Text); + var msg = cmd.Parameters.Add("$msg", SqliteType.Text); + var det = cmd.Parameters.Add("$details", SqliteType.Text); + var start = new DateTimeOffset(2026, 1, 1, 0, 0, 0, TimeSpan.Zero); + var rnd = new Random(7); + for (var i = 0; i < rows; i++) + { + id.Value = Guid.NewGuid().ToString(); + ts.Value = start.AddSeconds(i).ToString("o"); + inst.Value = i % 3 == 0 ? DBNull.Value : Guid.NewGuid().ToString(); + msg.Value = $"Script 'Recipe{i % 50}' completed in {rnd.Next(1, 900)} ms"; + det.Value = details is not null && rnd.NextDouble() < detailsFraction ? details : (object)DBNull.Value; + cmd.ExecuteNonQuery(); + } + tx.Commit(); + }); + + var estimated = purge.EstimateSiteEventsSize().EstimatedBytes; + var actual = purge.GetDatabaseSizeBytes() - baselineBytes; + var error = (estimated - (double)actual) / actual; + + _output.WriteLine($"{name}: rows={rows} estimated={estimated} actual={actual} error={error:P1}"); + + Assert.InRange(error, -0.05, 0.25); + } + + // ── wipe-prevention backstops ── + + /// Purge service whose size estimate and row count can be pinned by a test. + private sealed class StubbedEstimatePurgeService( + SiteEventLogger eventLogger, + IOptions options, + ILogger logger, + EventLogPurgeService.SiteEventsSizeEstimate? estimate, + long? frozenRowCount) + : EventLogPurgeService(eventLogger, options, logger) + { + internal override EventLogPurgeService.SiteEventsSizeEstimate EstimateSiteEventsSize() => + estimate ?? base.EstimateSiteEventsSize(); + + internal override long GetSiteEventsRowCount() => + frozenRowCount ?? base.GetSiteEventsRowCount(); + } + + [Fact] + public void PurgeByStorageCap_WhenRowWidthCannotBeSampled_DeletesNothingAndWarns() + { + // First backstop. A zero row width makes "how many rows put us under cap" unanswerable. + // The old loop's answer to an unanswerable cap was to keep deleting until the file + // shrank, which is precisely how a cap that can never be met empties a table. + SeedEvents(2000); + + var logger = new CapturingLogger(); + var purge = new StubbedEstimatePurgeService( + _eventLogger, + Options.Create(CapOptions(0)), + logger, + new EventLogPurgeService.SiteEventsSizeEstimate(RowCount: 2000, BytesPerRow: 0), + frozenRowCount: null); + + purge.RunPurge(); + + Assert.Equal(2000, EventCount()); + Assert.Contains(logger.Entries, e => + e.Level == LogLevel.Warning && e.Message.Contains("row width could not be sampled", StringComparison.Ordinal)); + } + + [Fact] + public void PurgeByStorageCap_WhenTheTableStopsShrinking_StopsRatherThanEmptyingTheLog() + { + // Second backstop, carried over from the old "size did not decrease" guard but re-based + // onto the table-scoped metric. It can no longer be tripped by replication bookkeeping; + // a frozen row count is what it now models — writers arriving as fast as the trim deletes. + SeedEvents(5000); + + var logger = new CapturingLogger(); + var purge = new StubbedEstimatePurgeService( + _eventLogger, + Options.Create(CapOptions(0)), // a 0 MB cap would otherwise delete every row + logger, + estimate: null, + frozenRowCount: 5000); + + purge.RunPurge(); + + var remaining = EventCount(); + Assert.True(remaining > 0, "The guard must stop the trim before the table is emptied."); + Assert.True(remaining >= 4000, $"Only one batch should have been deleted; {5000 - remaining} rows went."); + Assert.Contains(logger.Entries, e => + e.Level == LogLevel.Warning && e.Message.Contains("did not decrease", StringComparison.Ordinal)); + } + + private sealed record LogEntry(LogLevel Level, string Message); + + private sealed class CapturingLogger : ILogger + { + public List Entries { get; } = []; + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) => + Entries.Add(new LogEntry(logLevel, formatter(state, exception))); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/SqliteCapabilityTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/SqliteCapabilityTests.cs new file mode 100644 index 00000000..c46dc380 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests/SqliteCapabilityTests.cs @@ -0,0 +1,84 @@ +using Microsoft.Data.Sqlite; + +namespace ZB.MOM.WW.ScadaBridge.SiteEventLogging.Tests; + +/// +/// Pins the two SQLite provider capabilities the storage cap's size model depends on +/// (register row 81, docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md). +/// +/// +/// The intended fix for row 81 was to measure site_events' own pages exactly through the +/// dbstat virtual table. These tests are the evidence that this is not possible with the +/// native SQLite this solution ships, and the tripwire that will tell us if that ever changes — +/// if dbstat appears, the modelled estimate in +/// should be replaced by a real +/// measurement. +/// +public class SqliteCapabilityTests +{ + private static SqliteConnection OpenMemory() + { + var connection = new SqliteConnection("Data Source=:memory:"); + connection.Open(); + return connection; + } + + [Fact] + public void DbStat_IsNotAvailable_SoThePerTablePageCountMustBeModelled() + { + // If this test starts FAILING, that is good news, not a regression: the bundled + // e_sqlite3 has gained SQLITE_ENABLE_DBSTAT_VTAB and the cap can measure + // `SELECT sum(pgsize) FROM dbstat WHERE name='site_events'` exactly instead of + // modelling it. Delete the model, not this expectation, if that day comes. + using var connection = OpenMemory(); + + using var compileOptions = connection.CreateCommand(); + compileOptions.CommandText = "PRAGMA compile_options"; + var options = new List(); + using (var reader = compileOptions.ExecuteReader()) + { + while (reader.Read()) + options.Add(reader.GetString(0)); + } + + Assert.DoesNotContain("ENABLE_DBSTAT_VTAB", options); + + using var modules = connection.CreateCommand(); + modules.CommandText = "SELECT name FROM pragma_module_list"; + var names = new List(); + using (var reader = modules.ExecuteReader()) + { + while (reader.Read()) + names.Add(reader.GetString(0)); + } + + // The list is non-empty (fts3/4/5, rtree, geopoly …) so an empty result is not being + // mistaken for "no dbstat". + Assert.NotEmpty(names); + Assert.DoesNotContain("dbstat", names); + Assert.DoesNotContain("sqlite_dbpage", names); + + using var query = connection.CreateCommand(); + query.CommandText = "SELECT sum(pgsize) FROM dbstat"; + var ex = Assert.Throws(() => query.ExecuteScalar()); + Assert.Contains("dbstat", ex.Message, StringComparison.OrdinalIgnoreCase); + } + + [Fact] + public void OctetLength_IsAvailable_SoRowWidthIsSampledInBytesNotCharacters() + { + // The size model samples row width with octet_length() (SQLite 3.43+). length() counts + // CHARACTERS, so a multi-byte UTF-8 message would be under-sized and the cap enforced + // late. A provider downgrade that drops octet_length must fail here rather than + // silently shrinking every estimate at runtime. + using var connection = OpenMemory(); + + using var cmd = connection.CreateCommand(); + cmd.CommandText = "SELECT octet_length('skål'), length('skål')"; + using var reader = cmd.ExecuteReader(); + + Assert.True(reader.Read()); + Assert.Equal(5, reader.GetInt32(0)); // 'å' is two bytes in UTF-8 + Assert.Equal(4, reader.GetInt32(1)); + } +}