Files
ScadaBridge/docs/requirements/Component-SiteEventLogging.md
T
Joseph Doherty 6c11362d9f fix(auditlog)+fix(siteeventlog): complete audit write tasks only after commit; run event-log retention on standby (arch-review 2026-08-19 P4-2 + P4-4)
P4-2: SqliteAuditWriter.FlushBatch completed each pending row's Task
(TrySetResult) inside the per-row insert loop, before transaction.Commit()
ran. A later failure in the same batch (another row's insert throwing, or
the commit itself failing) rolled the whole transaction back, but the
earlier rows' Tasks had already completed successfully -- the caller and
FallbackAuditWriter (whose ring-buffer fallback exists precisely for this
outage) both saw false success while the rows were actually gone from the
database; the outer catch's TrySetException became a silent no-op against
an already-completed TaskCompletionSource. Every row's Completion is now
deferred and only resolved (TrySetResult for the whole batch, or
TrySetException for the whole batch) after transaction.Commit() succeeds
or the transaction rolls back, mirroring SiteEventLogger.FlushBatch.

P4-4: EventLogPurgeService gated the daily site_events purge on the
active-node check, early-exiting on the standby, on the stale premise that
"the standby receives no writes". DataConnectionActor runs on both site
nodes and writes site_events regardless of active/standby status (register
rows 89/90/97), so an unreplicated standby (the rig's site-b/site-c
posture) grew its site_events file forever with no retention and no cap.
The gate is removed; every node now purges its own file every tick. Safe
on a replicated pair because the retention/cap deletes are CDC-captured
and converge under LWW regardless of which node issues them; required on
an unreplicated pair because each node's file is independent. The
active-node check is retained only to annotate the purge tick's log line.

Tests: new SqliteAuditWriterCommitFailureTests forces a genuine
non-swallowed mid-batch INSERT failure via a real SQLite trigger + custom
scalar function on the writer's own connection (reflection seam), proving
(a) a row whose own insert succeeded still faults when a later row in the
same batch fails, and (b) FallbackAuditWriter rings every faulted row and
increments the failure counter for each -- both assertions fail against
the pre-fix code (proof-of-failure verified by temporarily reverting the
fix). EventLogPurgeServiceTests' standby case is inverted to assert the
purge now runs (not skips) on a standby node.
2026-08-19 14:49:24 -04:00

17 KiB
Raw Blame History

Component: Site Event Logging

Purpose

The Site Event Logging component records operational events at each site cluster, providing a local audit trail of runtime activity. Events are queryable from the central UI for remote troubleshooting.

Location

Site clusters (event recording and storage). Central cluster (remote query access via UI).

Responsibilities

  • Record operational events from all site subsystems.
  • Persist events to local SQLite.
  • Enforce 30-day retention policy with automatic purging.
  • Respond to remote queries from central for event log data.

Events Logged

Category Events
Script Executions Script started, completed (sampled/opt-in — see Volume Policy below); failed, timed out, recursion limit exceeded (with error details; always logged)
Script Run Summary Interval aggregate replacing the per-run rows by default — one Info row per flush interval summarizing every instance script run since the last flush (see Volume Policy)
Alarm Events Alarm activated, alarm cleared (which alarm, which instance), alarm evaluation error
Deployment Events Configuration received from central, scripts compiled, applied successfully, apply failed
Data Connection Status Connected, disconnected, reconnected (per connection)
Store-and-Forward Message queued, delivered, retried, parked
Instance Lifecycle Instance enabled, disabled, deleted
Notification Site→central forward failure, long-buffered notification (still in the site buffer past a threshold)

Volume Policy — Script Run Events (WP3.2, 2026-08-15)

Per-run instance-script Started/Completed Info events were, before this policy, the dominant site_events writer: two rows per run, translating to roughly a dozen physical row-writes across a replicated site pair once CDC oplog/row-version rows and their eventual purge tombstones are counted — for content nobody looks at unless something went wrong. The policy below (design memo: docs/plans/2026-08-15-site-events-policy-design.md) keeps the signal while removing the volume.

  • Off by default. ScadaBridge:SiteRuntime:PerRunScriptEvents (default false) is the global switch back to the legacy per-run Started/Completed rows for every script.
  • Interval aggregate instead. ScriptRunSummaryRecorder accumulates per-(instance, script) counters (started, completed, failed, timed out, total/max duration) from the same call sites that used to emit the per-run rows. A hosted flush service emits one "script" Info row per interval — ScadaBridge:SiteRuntime:ScriptRunSummaryIntervalSeconds (default 300, i.e. 5 minutes; 0 disables the flush) — with headline totals in the message (e.g. "1,243 runs: 1,240 completed, 2 failed, 1 timed out across 17 scripts") and a per-script breakdown in Details, capped at the top 50 scripts by run activity with an "others" rollup entry so a pathological deployment cannot mint an oversized row. An interval with zero activity emits no row — the standby, which never runs scripts, therefore never produces a summary row naturally. Source is "ScriptRunSummary"; Instance ID is NULL (the row spans every instance).
  • Per-script opt-in for debugging. ScadaBridge:SiteRuntime:PerRunScriptEventScripts (default empty) restores the legacy per-run rows for named scripts only, without paying the volume cost for the rest of the deployment. Entries are "{InstanceName}/{ScriptName}" for an exact match or "{InstanceName}/*" for every script on that instance. Effective only while the global switch is off.
  • Hot-togglable. Both keys are read from the live options snapshot at the top of every run (IOptionsMonitor<SiteRuntimeOptions>.CurrentValue), so an operator can flip either one — including narrowing an opt-in to a single misbehaving script — without a restart or a redeploy.
  • Error-level events are unconditional. Timeout, failure, stuck-watchdog, and recursion-limit Error rows are unaffected by any of the above — they always fire, regardless of PerRunScriptEvents or the opt-in list.

Event Entry Schema

Each event entry contains:

  • Timestamp: When the event occurred.
  • Event Type: Category of the event (script, alarm, deployment, connection, store-and-forward, instance-lifecycle, notification).
  • Severity: Info, Warning, or Error.
  • Instance ID (optional): The instance associated with the event (if applicable).
  • Source: The subsystem that generated the event (e.g., "ScriptActor:MonitorSpeed", "AlarmActor:OverTemp", "DataConnection:PLC1").
  • Message: Human-readable description of the event.
  • Details (optional): Additional structured data (e.g., exception stack trace, alarm name, message ID, compilation errors).

Storage

  • Events are stored in the consolidated site LocalDb SQLite file (site_events table; see CLAUDE.md → Consolidated site database). The active node generates most events (a standby runs no scripts, subsystems, or deployments to log), but DataConnectionActor runs on both site nodes and writes its own site_events rows regardless of active/standby status (register rows 89/90/97) — see Retention below for the purge consequence.
  • site_events IS replicated (SiteLocalDbSetup.ReplicatedTables) on a site pair with replication configured — this reverses the component's pre-LocalDb-Phase-1 behavior, and the reason is failover history continuity, not either-node queries: the query handler (EventLogHandlerActor) is a cluster singleton, so a central query always routes to the actively-written copy regardless of which node answers the gRPC call — replication is never needed to make queries work. What replication buys is content to read after a failover: when the active node dies, the singleton restarts on the survivor, and its query service reads the survivor's local copy — which has history only because it was replicated. Without replication, a failover would start the event log empty at precisely the moment an operator is investigating an incident (WP3.2 design memo, Decision (b): docs/plans/2026-08-15-site-events-policy-design.md). On a site pair running without replication configured (by deliberate choice, e.g. the 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 every site node (arch-review 2026-08-19 P4-4 — previously active-node-only, but the standby writes its own site_events rows too, so an unreplicated standby's file grew unbounded under the old active-only gate) and deletes that node's own 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 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 stops at the ceiling schedules the next tick after PurgeCatchUpInterval (default 5 minutes) instead of PurgeInterval, so retention still converges: a worst-case backlog drains over ~11 accelerated ticks (≈55 minutes) rather than 11 days at the daily cadence, with every individual burst bounded. The ceiling exists because the purge is CDC-captured (next bullet) and an unbounded tick could exceed LocalDb's oplog budget; measured evidence and the chosen defaults are in docs/plans/2026-08-15-site-events-purge-burst-measurement.md. A ceiling-limited tick logs a Warning (rate-limited to one line per 15 minutes) and increments scadabridge.site.event_log.purge_ceiling_hits — the counter is the unthrottled series that distinguishes a backlog converging from a site whose event rate outruns one paced tick. Consequence of the accelerated retry: the purge loop is a delay loop, not a PeriodicTimer, so the cadence is anchored to the end of the previous purge rather than to process start.
  • Purge deletes are CDC-captured on a replicated site — the resulting backlog spike is expected. Retention and cap deletes are ordinary row changes on a replicated table; there is deliberately no purge-exemption path (LocalDb Phase 2 — CDC does all three jobs, and a table-wide exemption is the same mechanism that made ReplaceAllAsync unsafe). One oplog row is queued per deleted event, so the site health report's LocalDbOplogBacklog (Prometheus localdb_oplog_depth) jumps by the size of the batch at purge time and drains as the peer acks it. The height of that jump is bounded by MaxPurgedRowsPerTick, not by how much history expired — measured (register row 34): a full 1 GB event log holds ~2.73 million rows at 393 bytes/row, and purging it unbounded queued 2 731 947 oplog rows, 2.7x LocalDb's MaxOplogRows default of 1 000 000, which would make the maintenance tick prune the oplog and flag a full ten-table snapshot resync. How much of that is resident depends on the peer — the oplog drains concurrently, and a loopback peer held the same burst to a 391 000 peak — so the overrun is conditional on peer throughput and unconditional when the peer is down. Bounding the tick is what makes the outcome independent of the peer. Pacing the tick, not exempting the purge from capture, is the fix — the exemption remains ruled out. Healthy signature: LocalDbReplicationConnected stays true across the spike and the backlog returns to ~0; a backlog that keeps climbing, or climbs while LocalDbReplicationConnected is false, is a genuine 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. 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 — including that the purge timer is anchored to the active node's process start, not a wall-clock hour — is in docs/deployment/topology-guide.md → Reading the replication backlog. See also the Volume Policy section above for why this residual cost is small now that per-run script rows are off by default.

Central Access

  • The central UI can query site event logs remotely via the Communication Layer.
  • Queries support filtering by:
    • Event type / category
    • Time range
    • Instance ID
    • Severity
    • Keyword search: Free-text search on message and source fields (SQLite LIKE query). Useful for finding events by script name, alarm name, or error message across all instances.
  • Results are paginated with a configurable page size (default: 500 events). Each response includes a continuation token for fetching additional pages. This prevents broad queries from overwhelming the communication channel.
  • The site processes the query locally against SQLite and returns matching results to central.

Dependencies

  • SQLite: Local storage on each site node.
  • Communication Layer: Handles remote query requests from central.
  • Site Runtime: Generates script execution events, alarm events, deployment application events, and instance lifecycle events.
  • Data Connection Layer: Generates connection status events.
  • Store-and-Forward Engine: Generates buffer activity events, including notification-category forward failures and long-buffered notifications on the site→central notification path.

Interactions

  • All site subsystems: Event logging is a cross-cutting concern — any subsystem that produces notable events calls the Event Logging service.
  • Communication Layer: Receives remote queries from central and returns results.
  • Central UI: Site Event Log Viewer displays queried events.
  • Store-and-Forward Engine: Its notification path (the site→central forward of script-generated notifications) reports forward failures and long-buffered notifications as Notification-category events. Routine enqueue and forward-success events are deliberately not logged — central's authoritative Notifications table (owned by the Notification Outbox component) is the audit record of record; site-side logging covers only the in-transit blind spot when central is unreachable.
  • Health Monitoring: Script error rates and alarm evaluation error rates can be derived from event log data; this component also reports SiteEventLogWriteFailures, and its purge is the expected cause of the transient LocalDbOplogBacklog spikes described in Component-HealthMonitoring.md → Monitored Metrics.