Files
ScadaBridge/docs/requirements/Component-SiteEventLogging.md
T
Joseph Doherty d9a35846d9 perf(siteeventlog): pace the site_events purge burst — per-tick delete ceiling + accelerated catch-up (row 34)
Measured the unbounded purge burst and found it can force a full ten-table
snapshot resync, then bounded it. No purge-exemption path was added — the
deletes are still CDC-captured like any other write, which stays ruled out
by design; what changed is how many a single tick performs.

MEASURED (harness: real EventLogPurgeService over a real LocalDb file with
site_events genuinely RegisterReplicated, plus a two-node loopback gRPC
replication pair; docker rig untouched):

  393 bytes/row incl. indexes => a 1 GB event log holds ~2,731,947 rows.
  Expiring all of them in ONE tick:  285 s, 2,731,947 oplog rows,
  284 MB oplog payload, 2.73 M row-version tombstones (7-day retention),
  i.e. 2.7x LocalDb's MaxOplogRows default of 1,000,000. Crossing that makes
  the 60 s maintenance tick prune the oplog and set needs_snapshot — a FULL
  snapshot of all ten replicated tables, bought by a routine retention purge.

  The resident backlog is produced-minus-drained, so a healthy peer blunts it:
  on loopback the same burst peaked at 391,424 and cleared in 6.0 min. That is
  the problem, not the reassurance — the old safety margin was a function of
  peer throughput and vanished with the peer down. A bounded tick is safe at
  any peer speed.

  Drain is not a bottleneck: 7.6k-19.8k tombstones/s (20k / 500k / 2.73M runs).

SHIPPED:
  - SiteEventLogOptions.MaxPurgedRowsPerTick (default 250,000; 0 = unlimited
    escape hatch, negatives rejected). One SHARED budget across the retention
    purge and the cap trim — two independently-capped phases would let a tick
    emit twice the intended burst. 4x margin under MaxOplogRows, which is also
    shared with every other replicated table's ordinary traffic.
  - SiteEventLogOptions.PurgeCatchUpInterval (default 5 min, validated > 0 and
    <= PurgeInterval). Without it pacing would make retention converge in 11
    DAYS at the daily cadence; with it the worst case converges in ~11 ticks
    (~55 min), every burst bounded. 5 min rather than 1 so ticks cannot outrun
    the peer's drain and re-accumulate the backlog.
  - A ceiling is claimed only when work genuinely remains (bounded EXISTS probe),
    so an expired set landing exactly on the budget does not arm a no-op retry.
  - Visibility: rate-limited (15 min) Warning naming the ceiling and the
    accelerated interval, plus an unthrottled counter
    scadabridge.site.event_log.purge_ceiling_hits — its SHAPE distinguishes a
    backlog converging from a site whose event rate outruns one paced tick.
  - The purge loop is a delay loop rather than a PeriodicTimer, so its cadence
    now anchors to the END of the previous purge. Documented.

ROW-33 INTERPLAY VERIFIED: pacing lowers each spike and lengthens total purge
duration, but a full 250k tick drains in ~23 s (~4 min even at 10x a real
link's penalty) against the 15-minute sustained dwell and a 5-minute gap to
the next tick. The UNPACED 2.73M burst had only 2.5x of margin (6.0 min), so
pacing makes the badge assumption robust rather than merely preserving it.

Docs travel together: Component-SiteEventLogging.md, topology-guide.md
("Reading the replication backlog" + the row-33 badge note), CLAUDE.md's
purge-burst sentence, and a dated measurement/decision note under docs/plans/.

Fail-before: the new behavioural tests do not compile against the pre-fix
service (RunPurge was void); with PurgeBudget neutralised to always-unlimited,
6 of the new tests fail and all 19 pre-existing ones pass.

Tests: SiteEventLogging 93/93, Commons 715/715, HealthMonitoring 115/115,
Host 505/505. Solution build clean.
2026-08-16 04:05:21 -04:00

13 KiB

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). Only the active node generates and stores events (a standby runs no scripts, subsystems, or deployments to log).
  • 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 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.
  • 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. 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.