From c254d0740e3d1ba75b0524975cc0185ed7a60c33 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Fri, 14 Aug 2026 22:56:08 -0400 Subject: [PATCH] perf(sitelog): sampled per-run events; interval run summaries; site_events replication policy pinned MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Implements WP3.2 stage (b) per docs/plans/2026-08-15-site-events-policy-design.md. - Per-run instance-script Started/Completed Info site events are now off by default (SiteRuntimeOptions.PerRunScriptEvents=false) instead of firing on every run, closing the dominant site_events writer. Gated at the ScriptRunLauncher call sites (moved there from ScriptExecutionActor by WP3.1). Error-level events (timeout/failure/stuck-watchdog/recursion-limit) remain unconditional. - ScriptRunSummaryRecorder accumulates per-(instance, script) run counters and a new site-only ScriptRunSummaryFlushService emits one aggregate "script" Info site event per ScriptRunSummaryIntervalSeconds (default 300s), top-50-script breakdown with an "others" rollup, zero-activity intervals emit nothing. - Per-script opt-in via PerRunScriptEventScripts ("Instance/Script" exact or "Instance/*" wildcard), matched by the new pure ScriptRunEventPolicy. All three options are read from IOptionsMonitor per run, so the policy is hot-togglable without a restart. - Fixed the stale "event log is not replicated" comment at AkkaHostedService.cs (~905): site_events IS registered in SiteLocalDbSetup.ReplicatedTables — the singleton is what makes queries always hit the actively-written copy; replication is what gives the singleton history to read after a failover (memo Decision (b)). site_events replication itself is unchanged (still registered) and already pinned by tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SiteLocalDbCdcRegistrationTests.cs. - Updated Component-SiteEventLogging.md (Volume Policy section, corrected Storage/replication rationale) and Component-SiteRuntime.md (Script Run Launch + Error Handling sections). --- .../Component-SiteEventLogging.md | 58 ++++- docs/requirements/Component-SiteRuntime.md | 3 +- .../Actors/AkkaHostedService.cs | 13 +- .../Scripts/ScriptRunEventPolicy.cs | 55 +++++ .../Scripts/ScriptRunLauncher.cs | 56 ++++- .../Scripts/ScriptRunSummaryFlushService.cs | 84 +++++++ .../Scripts/ScriptRunSummaryRecorder.cs | 205 ++++++++++++++++++ .../ServiceCollectionExtensions.cs | 13 ++ .../SiteRuntimeOptions.cs | 40 ++++ .../SiteRuntimeOptionsValidator.cs | 5 + .../Actors/ScriptRunLauncherParityTests.cs | 113 +++++++++- .../Scripts/ScriptRunEventPolicyTests.cs | 84 +++++++ .../Scripts/ScriptRunSummaryRecorderTests.cs | 169 +++++++++++++++ .../TestSupport/FakeSiteEventLogger.cs | 22 +- .../TestSupport/TestOptionsMonitor.cs | 29 +++ 15 files changed, 922 insertions(+), 27 deletions(-) create mode 100644 src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunEventPolicy.cs create mode 100644 src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryFlushService.cs create mode 100644 src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunEventPolicyTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/TestOptionsMonitor.cs diff --git a/docs/requirements/Component-SiteEventLogging.md b/docs/requirements/Component-SiteEventLogging.md index b568b5a4..3aede853 100644 --- a/docs/requirements/Component-SiteEventLogging.md +++ b/docs/requirements/Component-SiteEventLogging.md @@ -19,7 +19,8 @@ Site clusters (event recording and storage). Central cluster (remote query acces | Category | Events | |----------|--------| -| Script Executions | Script started, completed, failed (with error details), recursion limit exceeded | +| 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) | @@ -27,6 +28,41 @@ Site clusters (event recording and storage). Central cluster (remote query acces | 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.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: @@ -40,9 +76,23 @@ Each event entry contains: ## Storage -- Events are stored in **local SQLite** on each site node. -- Each node maintains its own event log. Only the **active node** generates and stores events. Event logs are **not replicated** to the standby node. On failover, the new active node starts logging to its own SQLite database; historical events from the previous active node are no longer queryable via central until that node comes back online. This is acceptable because event logs are diagnostic, not transactional. -- **Retention**: 30 days. A **daily background job** runs on the active node and deletes all events older than 30 days. Hard delete — no archival. +- 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. (Today, retention/cap deletes on a replicated node are captured by CDC like any other write — see the Volume Policy section above for why this is a small residual cost now that per-run rows are off by default.) - **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. ## Central Access diff --git a/docs/requirements/Component-SiteRuntime.md b/docs/requirements/Component-SiteRuntime.md index d9576841..f539e5cf 100644 --- a/docs/requirements/Component-SiteRuntime.md +++ b/docs/requirements/Component-SiteRuntime.md @@ -221,6 +221,7 @@ When the Instance Actor is stopped (due to disable, delete, or redeployment), Ak - A run is launched **directly by the Script Actor** through `ScriptRunLauncher`. There is no per-run child actor. - The former `ScriptExecutionActor` / `AlarmExecutionActor` were already inert shells: neither declared a `Receive` handler (they executed from their constructor), neither had a `PostStop`, state, or stash, and neither's `IActorRef` was ever a message target — the whole lifecycle lived inside a detached task the actor never observed. What they cost was an actor cell, mailbox, and name registration **per run**, plus a per-spawn expression-tree `Props.Create`. Removing them changed no semantics; the run body moved verbatim into the shared launcher. - Everything the shells provided is preserved: exception and timeout containment, one DI scope per run disposed on every path, the site-event/health telemetry, the Ask reply, the completion notification (now the coordinator's own `Self`), and the audit `ExecutionId` / `ParentExecutionId` threading. A run still in flight when its Script Actor is stopped runs to completion and its completion message dead-letters, exactly as before — **stopping does NOT cancel in-flight runs**; redeploy/undeploy semantics are unchanged. + - **Per-run Started/Completed site events are sampled, not unconditional (WP3.2).** The two Info rows an instance script run used to emit unconditionally were the dominant `site_events` writer under load (design memo: `docs/plans/2026-08-15-site-events-policy-design.md`). They are now **off by default** (`ScadaBridge:SiteRuntime:PerRunScriptEvents`, default `false`); a `ScriptRunSummaryRecorder` accumulates per-`(instance, script)` run counters from the same call sites and a site-only hosted flush service emits **one aggregate "script" Info row per interval** (`ScriptRunSummaryIntervalSeconds`, default 300s) with a top-50-scripts breakdown, capped so a pathological deployment cannot mint an oversized row — an idle interval emits nothing. `ScadaBridge:SiteRuntime:PerRunScriptEventScripts` restores the legacy per-run rows for named scripts (`"Instance/Script"` exact or `"Instance/*"` wildcard) for live debugging. All three keys are read from `IOptionsMonitor` per run, so they are hot-togglable without a restart. **Error-level rows (timeout, failure, stuck-watchdog, recursion-limit) are unaffected — always emitted, regardless of this policy.** See Component-SiteEventLogging.md → Volume Policy for the full design. - One deliberate improvement: a failure of the *launch itself* (e.g. queueing onto a disposed scheduler) is caught by the Script Actor, which replies to the Ask caller and releases the run slot. The old per-run child's constructor throw was handled by a Stop supervision directive that sent no reply, leaving the caller to hang to its Ask timeout. - The script body runs on the **dedicated `ScriptExecutionScheduler`** (a bounded set of dedicated threads), not the shared .NET thread pool, so blocking script I/O cannot starve the global pool or stall Akka dispatchers. The scheduler is **process-wide by default** (one pool per host), but each script/alarm actor takes it through an **optional injection seam** rather than reaching for the static directly: the Host injects nothing and gets the shared pool, while tests (or a future multi-site host) can hand an actor its own instance. The shared accessor also recreates a disposed pool rather than returning it, so a disposed scheduler can never silently poison later executions. - **Pool sizing is instance-scaled and grow-only (WP3.1).** The pool was a fixed 8 threads regardless of load. It is now `clamp(max(ScriptExecutionThreadCount, ceil(enabledInstances / 8)), 1, ScriptExecutionMaxThreadCount)` — the existing `ScriptExecutionThreadCount` (default 8) becomes the **floor**, so configurations at or below 64 instances behave exactly as before, and the new `ScriptExecutionMaxThreadCount` (default 32) is the ceiling. Beyond the ceiling the per-script cap below is the real regulator. `DeploymentManagerActor.UpdateInstanceCounts` calls `EnsureCapacity` on every deploy / undeploy / enable / disable and once per staggered startup batch. Growth only: undeploying leaves idle threads, which cost nothing measurable and avoid drain/steal complexity. @@ -531,7 +532,7 @@ Per Akka.NET best practices, internal actor communication uses **Tell** (fire-an ## Error Handling ### Script Errors -- Unhandled exceptions and timeouts in Script Execution Actors are **logged locally** to the site event log. +- Unhandled exceptions and timeouts in a script run are **logged locally** to the site event log — unconditionally, regardless of the WP3.2 per-run Started/Completed sampling policy (see Script Run Launch above). - The Script Actor (coordinator) is **not affected** — it remains active for future trigger events. - Script failures are **not reported to central** (except as aggregated error rate metrics via Health Monitoring). diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs index 985bb4e6..c6e7f9bc 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs @@ -902,10 +902,15 @@ akka {{ // Register local handlers with SiteCommunicationActor siteCommActor.Tell(new RegisterLocalHandler(LocalHandlerType.Artifacts, dmProxy)); - // Event log handler — cluster singleton so queries always reach the - // active node. The event log is node-local SQLite and is not - // replicated; only the active node records events. A per-node handler - // would let a central query land on the standby and find nothing. + // Event log handler — cluster singleton so queries always reach the copy that is + // ACTIVELY BEING WRITTEN: the site_events table IS replicated (LocalDb Phase 1, + // SiteLocalDbSetup.ReplicatedTables), but replication alone would not save a + // per-node handler — central queries route through SiteCommandDispatcher to + // whichever node answers, and a standby's replica sits idle until failover. The + // singleton is what guarantees queries always read the actively-written copy; + // replication is what gives the singleton HISTORY to read after it moves — + // without it, a failover would restart the event log empty at exactly the moment + // an operator is investigating an incident (WP3.2 design memo, Decision (b)). var eventLogQueryService = _serviceProvider.GetService(); if (eventLogQueryService != null) { diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunEventPolicy.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunEventPolicy.cs new file mode 100644 index 00000000..66603f9e --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunEventPolicy.cs @@ -0,0 +1,55 @@ +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +/// +/// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md): +/// decides whether an instance script run should emit the legacy per-run Started/Completed +/// Info site events, or stay silent and let 's interval +/// aggregate carry the signal instead. Pure and side-effect-free — no DI, no actor context — +/// so the three opt-in shapes (global switch, exact per-script match, per-instance wildcard) +/// are unit-testable in isolation and reusable from without +/// dragging config plumbing into the run body. +/// +public static class ScriptRunEventPolicy +{ + /// + /// True when per-run Started/Completed Info events should be emitted for this run. + /// + /// + /// The effective snapshot for this run (the caller reads + /// IOptionsMonitor<SiteRuntimeOptions>.CurrentValue per run so this stays + /// hot-togglable — see ). + /// + /// The owning instance's name. + /// The script's name. + /// + /// true if is set, or if + /// contains an exact + /// "{instanceName}/{scriptName}" entry or an "{instanceName}/*" wildcard + /// entry for this instance; otherwise false. + /// + public static bool ShouldEmitPerRun(SiteRuntimeOptions options, string instanceName, string scriptName) + { + ArgumentNullException.ThrowIfNull(options); + + if (options.PerRunScriptEvents) + return true; + + var scripts = options.PerRunScriptEventScripts; + if (scripts is not { Count: > 0 }) + return false; + + var exact = $"{instanceName}/{scriptName}"; + var wildcard = $"{instanceName}/*"; + + foreach (var entry in scripts) + { + if (string.Equals(entry, exact, StringComparison.Ordinal) || + string.Equals(entry, wildcard, StringComparison.Ordinal)) + { + return true; + } + } + + return false; + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs index 4efc16cf..5a3c99ea 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs @@ -1,7 +1,9 @@ +using System.Diagnostics; using Akka.Actor; using Microsoft.CodeAnalysis.Scripting; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution; @@ -221,6 +223,20 @@ internal static class ScriptRunLauncher // it is available to the catch blocks regardless of scope state. var siteEventLogger = serviceProvider?.GetService(); + // WP3.2 (site_events volume policy): both are singletons, resolved from the root + // provider up front so they too are available to the catch blocks. optionsMonitor is + // null in tests that pass no serviceProvider (SingleServiceProvider et al.) — the + // constructor-passed `options` is the fallback, exactly like siteEventLogger's null + // path degrades to "no site event log". Reading CurrentValue HERE (once per run, at + // the top) rather than re-reading it at each call site is what "hot-togglable" means + // in practice: an operator's live edit to PerRunScriptEvents/PerRunScriptEventScripts + // takes effect on the NEXT run, without a restart. + var summaryRecorder = serviceProvider?.GetService(); + var optionsMonitor = serviceProvider?.GetService>(); + var effectiveOptions = optionsMonitor?.CurrentValue ?? options; + var emitPerRunEvents = ScriptRunEventPolicy.ShouldEmitPerRun(effectiveOptions, instanceName, scriptName); + var runStopwatch = Stopwatch.StartNew(); + // WP3.1: identify the worker this body is holding, so the watchdog can detach and // replace it if the body wedges. Read in the FIRST synchronous segment — a script // that later hops threads on an await no longer holds this worker, and the run-stamp @@ -350,12 +366,19 @@ internal static class ScriptRunLauncher Scope = scope }; - // Operational `script` event — execution started. Fire-and-forget - // (the `_ =` discards the task) so the event log can never block or - // fault the script's own run; mirrors the existing Error-path emit. - _ = siteEventLogger?.LogEventAsync( - "script", "Info", instanceName, $"ScriptActor:{scriptName}", - $"Script '{scriptName}' on instance '{instanceName}' started"); + // WP3.2: the aggregate ALWAYS records this run (that's the point of the interval + // summary), but the per-run Info event itself is gated by ScriptRunEventPolicy — + // off by default, on globally via PerRunScriptEvents, or on for named scripts via + // PerRunScriptEventScripts. Fire-and-forget (the `_ =` discards the task) so the + // event log can never block or fault the script's own run; mirrors the existing + // Error-path emit, which stays unconditional regardless of this policy. + summaryRecorder?.RecordStarted(instanceName, scriptName); + if (emitPerRunEvents) + { + _ = siteEventLogger?.LogEventAsync( + "script", "Info", instanceName, $"ScriptActor:{scriptName}", + $"Script '{scriptName}' on instance '{instanceName}' started"); + } var state = await compiledScript.RunAsync(globals, cts.Token); @@ -365,10 +388,15 @@ internal static class ScriptRunLauncher replyTo.Tell(new ScriptCallResult(correlationId, true, state.ReturnValue, null)); } - // Operational `script` event — execution completed successfully. - _ = siteEventLogger?.LogEventAsync( - "script", "Info", instanceName, $"ScriptActor:{scriptName}", - $"Script '{scriptName}' on instance '{instanceName}' completed"); + // Operational `script` event — execution completed successfully. Same gating as + // the started event above. + summaryRecorder?.RecordCompleted(instanceName, scriptName, runStopwatch.ElapsedMilliseconds); + if (emitPerRunEvents) + { + _ = siteEventLogger?.LogEventAsync( + "script", "Info", instanceName, $"ScriptActor:{scriptName}", + $"Script '{scriptName}' on instance '{instanceName}' completed"); + } // Notify the owning ScriptActor of completion (also releases its in-flight slot). completionTarget.Tell(new ScriptActor.ScriptExecutionCompleted(scriptName, true, null)); @@ -376,10 +404,12 @@ internal static class ScriptRunLauncher catch (OperationCanceledException) { healthCollector?.IncrementScriptError(); + summaryRecorder?.RecordTimedOut(instanceName, scriptName, runStopwatch.ElapsedMilliseconds); var errorMsg = $"Script '{scriptName}' on instance '{instanceName}' timed out after {timeout.TotalSeconds}s"; logger.LogWarning("{Message} (run {RunId})", errorMsg, runId); - // Failures recorded to site event log; script NOT disabled after failure. + // Failures recorded to site event log; script NOT disabled after failure. WP3.2: + // Error-level emissions are unconditional — never gated by ScriptRunEventPolicy. _ = siteEventLogger?.LogEventAsync( "script", "Error", instanceName, $"ScriptActor:{scriptName}", errorMsg); @@ -393,7 +423,9 @@ internal static class ScriptRunLauncher catch (Exception ex) { healthCollector?.IncrementScriptError(); - // Failures recorded to site event log; script NOT disabled after failure. + summaryRecorder?.RecordFailed(instanceName, scriptName, runStopwatch.ElapsedMilliseconds); + // Failures recorded to site event log; script NOT disabled after failure. WP3.2: + // Error-level emissions are unconditional — never gated by ScriptRunEventPolicy. var errorMsg = $"Script '{scriptName}' on instance '{instanceName}' failed: {ex.Message}"; logger.LogError(ex, "Script execution failed: {Script} on {Instance} (run {RunId})", scriptName, instanceName, runId); diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryFlushService.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryFlushService.cs new file mode 100644 index 00000000..26767e8a --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryFlushService.cs @@ -0,0 +1,84 @@ +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using ZB.MOM.WW.ScadaBridge.SiteEventLogging; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +/// +/// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md): +/// site-only hosted service that periodically flushes +/// into one aggregate "script" Info site event. Registered by +/// ServiceCollectionExtensions.AddSiteRuntime, which only the site composition root +/// calls (SiteServiceRegistration.Configure) — central never runs scripts, so central +/// never registers this service, which is what makes it "Site nodes only" per the design memo. +/// +/// The interval is read from on every tick (not +/// captured once at construction) so +/// is hot-reloadable — an operator can shorten or lengthen it, or disable it (0), live. +/// Mirrors ScriptSchedulerStatsReporter's shape: fixed cadence, exceptions logged and +/// swallowed so the loop survives every flush failure. +/// +public sealed class ScriptRunSummaryFlushService : BackgroundService +{ + /// Poll cadence used while summaries are disabled (ScriptRunSummaryIntervalSeconds == 0) — coarse enough to amortise re-checking whether the interval was re-enabled live. + private static readonly TimeSpan DisabledPollInterval = TimeSpan.FromSeconds(30); + + private readonly ScriptRunSummaryRecorder _recorder; + private readonly ISiteEventLogger _siteEventLogger; + private readonly IOptionsMonitor _optionsMonitor; + private readonly ILogger _logger; + + /// Initializes a new instance of . + /// The recorder whose accumulated counters this service flushes. + /// The site event logger the flushed summary row is written to. + /// Supplies the hot-reloadable flush interval. + /// Logger instance. + public ScriptRunSummaryFlushService( + ScriptRunSummaryRecorder recorder, + ISiteEventLogger siteEventLogger, + IOptionsMonitor optionsMonitor, + ILogger logger) + { + _recorder = recorder ?? throw new ArgumentNullException(nameof(recorder)); + _siteEventLogger = siteEventLogger ?? throw new ArgumentNullException(nameof(siteEventLogger)); + _optionsMonitor = optionsMonitor ?? throw new ArgumentNullException(nameof(optionsMonitor)); + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + } + + /// + protected override async Task ExecuteAsync(CancellationToken stoppingToken) + { + while (!stoppingToken.IsCancellationRequested) + { + var intervalSeconds = _optionsMonitor.CurrentValue.ScriptRunSummaryIntervalSeconds; + var wait = intervalSeconds > 0 ? TimeSpan.FromSeconds(intervalSeconds) : DisabledPollInterval; + + try + { + await Task.Delay(wait, stoppingToken).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + break; + } + + if (intervalSeconds <= 0) + { + // Summaries disabled for this tick's window: counters keep accumulating in + // the recorder (harmless — the next enabled flush just reports a longer + // window), we simply don't emit or reset yet. + continue; + } + + try + { + await _recorder.FlushAsync(_siteEventLogger).ConfigureAwait(false); + } + catch (Exception ex) + { + _logger.LogWarning(ex, "ScriptRunSummaryFlushService flush failed; next tick will retry."); + } + } + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs new file mode 100644 index 00000000..92196677 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunSummaryRecorder.cs @@ -0,0 +1,205 @@ +using System.Collections.Concurrent; +using System.Globalization; +using System.Text.Json; +using ZB.MOM.WW.ScadaBridge.SiteEventLogging; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +/// +/// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md): +/// accumulates per-(instance, script) run counters between flushes and emits ONE aggregate +/// "script" Info site event per interval instead of the two per-run Started/Completed rows +/// that were the dominant site_events writer. Registered as a process-wide singleton +/// (ServiceCollectionExtensions.AddSiteRuntime); incremented from the same +/// call sites that used to emit the per-run events, flushed +/// on a timer by ScriptRunSummaryFlushService. +/// +/// Lock-free: each script's counters are a small class of long fields mutated +/// via , reached through a +/// that atomically swaps out () so a +/// concurrent increment either lands in the snapshot being flushed or the fresh one that +/// replaces it — never lost, never double-counted, and the flush never blocks a recording +/// call (or vice versa). +/// +public sealed class ScriptRunSummaryRecorder +{ + /// + /// Per-script breakdown cap in the flushed details JSON — the rest fold into a single + /// "others" rollup entry so a deployment with hundreds of scripts cannot mint an + /// oversized site event row. + /// + internal const int TopScriptCap = 50; + + private sealed class Counters + { + public long Started; + public long Completed; + public long Failed; + public long TimedOut; + public long TotalDurationMs; + public long MaxDurationMs; + } + + private ConcurrentDictionary<(string InstanceName, string ScriptName), Counters> _counters = new(); + + private Counters GetOrAddCounters(string instanceName, string scriptName) => + Volatile.Read(ref _counters).GetOrAdd((instanceName, scriptName), static _ => new Counters()); + + /// Records that a script run began executing (past the shed-at-dequeue check). + public void RecordStarted(string instanceName, string scriptName) + { + var counters = GetOrAddCounters(instanceName, scriptName); + Interlocked.Increment(ref counters.Started); + } + + /// Records that a script run completed successfully. + public void RecordCompleted(string instanceName, string scriptName, long durationMs) + { + var counters = GetOrAddCounters(instanceName, scriptName); + Interlocked.Increment(ref counters.Completed); + RecordDuration(counters, durationMs); + } + + /// Records that a script run threw an unhandled exception. + public void RecordFailed(string instanceName, string scriptName, long durationMs) + { + var counters = GetOrAddCounters(instanceName, scriptName); + Interlocked.Increment(ref counters.Failed); + RecordDuration(counters, durationMs); + } + + /// + /// Records that a script run timed out — including a run shed at dequeue (its deadline + /// was already spent queueing, so it never reached ). + /// + public void RecordTimedOut(string instanceName, string scriptName, long durationMs) + { + var counters = GetOrAddCounters(instanceName, scriptName); + Interlocked.Increment(ref counters.TimedOut); + RecordDuration(counters, durationMs); + } + + private static void RecordDuration(Counters counters, long durationMs) + { + if (durationMs < 0) durationMs = 0; + Interlocked.Add(ref counters.TotalDurationMs, durationMs); + InterlockedMax(ref counters.MaxDurationMs, durationMs); + } + + /// Lock-free running-max update (no built-in Interlocked.Max(ref long, long)). + private static void InterlockedMax(ref long location, long candidate) + { + var initial = Volatile.Read(ref location); + while (candidate > initial) + { + var previous = Interlocked.CompareExchange(ref location, candidate, initial); + if (previous == initial) return; + initial = previous; + } + } + + /// + /// Snapshots and resets the accumulated counters, then — if any script ran, failed, or + /// timed out during the interval — emits ONE aggregate "script" Info site event + /// summarizing the window. An interval with zero activity emits no row (the standby, + /// which never runs scripts, therefore never produces a summary row naturally). + /// + /// The site event logger to emit the aggregate row to. + /// true if a summary row was emitted; false if the interval was idle. + public async Task FlushAsync(ISiteEventLogger siteEventLogger) + { + ArgumentNullException.ThrowIfNull(siteEventLogger); + + // The replacement dictionary's type argument must name its tuple elements + // IDENTICALLY to the field's declared type — Interlocked.Exchange is generic + // over both the ref and value parameters, and mixing a named-tuple exact bound + // with an unnamed one erases the names from the inferred T (and therefore from + // `snapshot` below). + var snapshot = Interlocked.Exchange( + ref _counters, + new ConcurrentDictionary<(string InstanceName, string ScriptName), Counters>()); + + var entries = snapshot + .Where(kvp => kvp.Value.Started > 0 || kvp.Value.Failed > 0 || kvp.Value.TimedOut > 0) + .ToList(); + + if (entries.Count == 0) + return false; + + long totalStarted = 0, totalCompleted = 0, totalFailed = 0, totalTimedOut = 0; + foreach (var entry in entries) + { + totalStarted += entry.Value.Started; + totalCompleted += entry.Value.Completed; + totalFailed += entry.Value.Failed; + totalTimedOut += entry.Value.TimedOut; + } + + // Rank by total run activity. Started+TimedOut (not just Started): a run shed at + // dequeue never reaches RecordStarted, so ranking on Started alone would silently + // drop a script that does nothing BUT get shed from the breakdown entirely. + var ranked = entries + .OrderByDescending(e => e.Value.Started + e.Value.TimedOut) + .ToList(); + + var top = ranked.Take(TopScriptCap); + var rest = ranked.Skip(TopScriptCap).ToList(); + + var breakdown = top.Select(e => new ScriptSummaryEntry( + e.Key.InstanceName, + e.Key.ScriptName, + e.Value.Started, + e.Value.Completed, + e.Value.Failed, + e.Value.TimedOut, + e.Value.Completed > 0 ? e.Value.TotalDurationMs / e.Value.Completed : 0, + e.Value.MaxDurationMs)).ToList(); + + object details; + if (rest.Count > 0) + { + details = new + { + scripts = breakdown, + others = new + { + scriptCount = rest.Count, + started = rest.Sum(e => e.Value.Started), + completed = rest.Sum(e => e.Value.Completed), + failed = rest.Sum(e => e.Value.Failed), + timedOut = rest.Sum(e => e.Value.TimedOut), + } + }; + } + else + { + details = new { scripts = breakdown }; + } + + var message = string.Format( + CultureInfo.InvariantCulture, + "{0:N0} runs: {1:N0} completed, {2:N0} failed, {3:N0} timed out across {4:N0} scripts", + totalStarted, totalCompleted, totalFailed, totalTimedOut, entries.Count); + + var detailsJson = JsonSerializer.Serialize(details, DetailsJsonOptions); + + await siteEventLogger.LogEventAsync( + "script", "Info", null, "ScriptRunSummary", message, detailsJson).ConfigureAwait(false); + + return true; + } + + // Built once per assembly (WP1.5 convention) rather than per flush. + private static readonly JsonSerializerOptions DetailsJsonOptions = + new() { PropertyNamingPolicy = JsonNamingPolicy.CamelCase }; + + private sealed record ScriptSummaryEntry( + string InstanceName, + string ScriptName, + long Started, + long Completed, + long Failed, + long TimedOut, + long AvgDurationMs, + long MaxDurationMs); +} diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ServiceCollectionExtensions.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ServiceCollectionExtensions.cs index 796a5e41..e94af366 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ServiceCollectionExtensions.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/ServiceCollectionExtensions.cs @@ -4,6 +4,7 @@ using Microsoft.Extensions.Options; using ZB.MOM.WW.LocalDb; using ZB.MOM.WW.ScadaBridge.Communication.Grpc; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Repositories; +using ZB.MOM.WW.ScadaBridge.SiteEventLogging; using ZB.MOM.WW.ScadaBridge.SiteRuntime.Deployment; using ZB.MOM.WW.ScadaBridge.SiteRuntime.Persistence; using ZB.MOM.WW.ScadaBridge.SiteRuntime.Repositories; @@ -98,6 +99,18 @@ public static class ServiceCollectionExtensions sp.GetRequiredService(), sp.GetRequiredService>())); + // WP3.2 (site_events volume policy): the recorder is a singleton so ScriptRunLauncher + // can resolve it from the root service provider on every run, the same way it already + // resolves ISiteEventLogger. The flush service is registered ONLY here — central + // composition roots never call AddSiteRuntime(), which is what makes the periodic + // "script" summary event site-only, matching the design memo. + services.AddSingleton(); + services.AddHostedService(sp => new ScriptRunSummaryFlushService( + sp.GetRequiredService(), + sp.GetRequiredService(), + sp.GetRequiredService>(), + sp.GetRequiredService>())); + return services; } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs index 2fe65424..e63d1bcc 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptions.cs @@ -141,4 +141,44 @@ public class SiteRuntimeOptions /// ). /// public int AlarmPublishQueueCapacity { get; set; } = 2000; + + /// + /// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md): + /// global switch restoring the legacy per-run Started/Completed Info site events for + /// EVERY instance script run. Off by default: those two rows per run were the dominant + /// site_events writer (~12 physical row-writes across a replicated pair per run, + /// counting CDC oplog + row-version rows and their eventual purge tombstones), for + /// content nobody looks at unless something went wrong. With this off, an interval + /// aggregate () replaces the per-run rows + /// and script Error events (timeout/failure/stuck-watchdog) are unaffected — they are + /// unconditional regardless of this switch. Read via + /// at the top of + /// every run, so it is hot-togglable (no restart, no redeploy). Default: false. + /// + public bool PerRunScriptEvents { get; set; } + + /// + /// WP3.2: per-script opt-in restoring the legacy per-run Started/Completed Info site + /// events for NAMED scripts only, for live debugging without flipping the global + /// switch (and therefore without paying its volume + /// cost for every other script). Effective only while the global switch is off. + /// Entries are "{InstanceName}/{ScriptName}" for an exact match, or + /// "{InstanceName}/*" to opt in every script on that instance. Matched by + /// , read from + /// per run — hot + /// -togglable like . Default: empty (no opt-ins). + /// + public List PerRunScriptEventScripts { get; set; } = new(); + + /// + /// WP3.2: flush interval (seconds) for 's + /// interval aggregate — one "script" Info site event per interval summarizing every + /// instance script run since the last flush (headline totals + a top-50-scripts + /// breakdown, capped so a pathological deployment cannot mint an oversized row). An + /// interval with zero activity emits no row. 0 disables the summary flush + /// entirely (the recorder still accumulates counters; they are just never emitted or + /// reset). Default: 300 (5 minutes) — at most 288 summary rows/day, versus 2 rows per + /// script run under the legacy per-run behaviour. + /// + public int ScriptRunSummaryIntervalSeconds { get; set; } = 300; } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs index f5e0f0a6..2fd1739b 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/SiteRuntimeOptionsValidator.cs @@ -86,5 +86,10 @@ public sealed class SiteRuntimeOptionsValidator : OptionsValidatorBase 0, $"ScadaBridge:SiteRuntime:AlarmPublishQueueCapacity must be greater than 0 " + $"(was {options.AlarmPublishQueueCapacity}); it bounds SiteStreamManager's dedicated alarm publish queue."); + + builder.RequireThat(options.ScriptRunSummaryIntervalSeconds >= 0, + $"ScadaBridge:SiteRuntime:ScriptRunSummaryIntervalSeconds must be >= 0 " + + $"(was {options.ScriptRunSummaryIntervalSeconds}); it is the ScriptRunSummaryRecorder " + + "flush interval and a negative value throws inside its delay. 0 disables the flush."); } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunLauncherParityTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunLauncherParityTests.cs index 830d4017..e452dc2c 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunLauncherParityTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunLauncherParityTests.cs @@ -64,12 +64,16 @@ public class ScriptRunLauncherParityTests : TestKit, IDisposable return script; } - private static SiteRuntimeOptions Options(int timeoutSeconds = 30, int graceMs = 30000) + private static SiteRuntimeOptions Options( + int timeoutSeconds = 30, int graceMs = 30000, bool perRunScriptEvents = false) => new() { MaxScriptCallDepth = 10, ScriptExecutionTimeoutSeconds = timeoutSeconds, - StuckScriptGraceMs = graceMs + StuckScriptGraceMs = graceMs, + // WP3.2: per-run Started/Completed Info events default OFF; tests that pin the + // legacy per-run event shape opt back in explicitly via this flag. + PerRunScriptEvents = perRunScriptEvents }; private static ResolvedScript CallScript(int? timeoutSeconds = null) => new() @@ -382,8 +386,10 @@ public class ScriptRunLauncherParityTests : TestKit, IDisposable public void SuccessfulRun_EmitsStartedThenCompletedInfoEvents() { var siteLog = new FakeSiteEventLogger(); + // WP3.2: per-run Info events are opt-in now (default off, interval summary instead) — + // this test pins the legacy per-run shape, so it opts back in explicitly. var actor = BuildScriptActor( - CompileScript("return 7 * 6;"), Options(), new SingleServiceProvider(siteLog)); + CompileScript("return 7 * 6;"), Options(perRunScriptEvents: true), new SingleServiceProvider(siteLog)); var caller = CreateTestProbe(); actor.Tell(new ScriptCallRequest("Runner", null, 0, "corr-evt"), caller.Ref); @@ -408,9 +414,11 @@ public class ScriptRunLauncherParityTests : TestKit, IDisposable public void FailingRun_EmitsStartedInfoThenErrorEvent() { var siteLog = new FakeSiteEventLogger(); + // WP3.2: the started Info event is opt-in (default off); the Error event on failure + // stays unconditional regardless. This test pins the opted-in shape explicitly. var actor = BuildScriptActor( CompileScript("throw new InvalidOperationException(\"boom\");"), - Options(), new SingleServiceProvider(siteLog)); + Options(perRunScriptEvents: true), new SingleServiceProvider(siteLog)); var caller = CreateTestProbe(); actor.Tell(new ScriptCallRequest("Runner", null, 0, "corr-evt-err"), caller.Ref); @@ -430,8 +438,11 @@ public class ScriptRunLauncherParityTests : TestKit, IDisposable public void FireAndForgetRun_NeedsNoReplyTarget() { var siteLog = new FakeSiteEventLogger(); + // WP3.2: opted in so the completed Info event (the observable proof the + // fire-and-forget run actually ran to completion) is emitted; the policy itself is + // covered separately by ScriptRunEventPolicyTests. var actor = BuildScriptActor( - CompileScript("return 1;"), Options(), new SingleServiceProvider(siteLog)); + CompileScript("return 1;"), Options(perRunScriptEvents: true), new SingleServiceProvider(siteLog)); // Trigger-driven spawns pass ActorRefs.NoSender as replyTo; drive that path via an // interval-free Call script by telling the actor to run with no sender. @@ -442,6 +453,98 @@ public class ScriptRunLauncherParityTests : TestKit, IDisposable r => r.Message.Contains("completed", StringComparison.OrdinalIgnoreCase)), TimeSpan.FromSeconds(10)); } + + // ── WP3.2: site_events volume policy — actor-level integration ──────────────── + // + // The pure ScriptRunEventPolicy matching rules (exact/wildcard/global/non-matching) are + // unit-tested directly in ScriptRunEventPolicyTests; these prove the policy is actually + // wired through the real ScriptActor -> ScriptRunLauncher path: the default is silent but + // the aggregate still sees the run, per-script opt-in works end to end, and the + // IOptionsMonitor read makes the switch hot-togglable without an actor restart. + + [Fact] + public async Task DefaultOptions_SuccessfulRun_EmitsNoPerRunEvents_ButTheSummaryRecorderSeesIt() + { + var siteLog = new FakeSiteEventLogger(); + var recorder = new ScriptRunSummaryRecorder(); + var actor = BuildScriptActor( + CompileScript("return 1;"), Options(), + new SingleServiceProvider(siteLog, summaryRecorder: recorder)); + + var caller = CreateTestProbe(); + actor.Tell(new ScriptCallRequest("Runner", null, 0, "corr-default-off"), caller.Ref); + caller.ExpectMsg(TimeSpan.FromSeconds(10)); + + // RecordCompleted happens-before the ScriptExecutionCompleted Tell that releases the + // in-flight slot (see RunScriptAsync), so waiting on RunsInFlight == 0 makes the + // subsequent flush deterministic — no sleep, no retry-flush race. + AwaitAssert(() => Assert.Equal(0, actor.UnderlyingActor.RunsInFlight), TimeSpan.FromSeconds(5)); + + Assert.Empty(siteLog.OfType("script")); + + var flushLog = new FakeSiteEventLogger(); + var emitted = await recorder.FlushAsync(flushLog); + Assert.True(emitted); + Assert.Equal( + "1 runs: 1 completed, 0 failed, 0 timed out across 1 scripts", + flushLog.OfType("script").Single().Message); + } + + [Fact] + public void PerScriptOptIn_ExactMatch_RestoresPerRunEventsForThatScriptOnly() + { + var siteLog = new FakeSiteEventLogger(); + var options = Options(); + options.PerRunScriptEventScripts = ["Inst1/Runner"]; + var actor = BuildScriptActor( + CompileScript("return 1;"), options, new SingleServiceProvider(siteLog)); + + var caller = CreateTestProbe(); + actor.Tell(new ScriptCallRequest("Runner", null, 0, "corr-exact-optin"), caller.Ref); + caller.ExpectMsg(TimeSpan.FromSeconds(10)); + + AwaitAssert(() => Assert.Equal(2, siteLog.OfType("script").Count), TimeSpan.FromSeconds(5)); + } + + [Fact] + public void PerScriptOptIn_InstanceWildcard_RestoresPerRunEvents() + { + var siteLog = new FakeSiteEventLogger(); + var options = Options(); + options.PerRunScriptEventScripts = ["Inst1/*"]; + var actor = BuildScriptActor( + CompileScript("return 1;"), options, new SingleServiceProvider(siteLog)); + + var caller = CreateTestProbe(); + actor.Tell(new ScriptCallRequest("Runner", null, 0, "corr-wildcard-optin"), caller.Ref); + caller.ExpectMsg(TimeSpan.FromSeconds(10)); + + AwaitAssert(() => Assert.Equal(2, siteLog.OfType("script").Count), TimeSpan.FromSeconds(5)); + } + + [Fact] + public void HotToggle_FlippingTheOptionsMonitor_ChangesTheNextRunWithNoActorRestart() + { + var siteLog = new FakeSiteEventLogger(); + var monitor = new TestOptionsMonitor(Options()); + var actor = BuildScriptActor( + CompileScript("return 1;"), Options(), new SingleServiceProvider(siteLog, monitor)); + + var caller = CreateTestProbe(); + + // Off: the monitor's initial value has PerRunScriptEvents=false. + actor.Tell(new ScriptCallRequest("Runner", null, 0, "corr-hot-1"), caller.Ref); + caller.ExpectMsg(TimeSpan.FromSeconds(10)); + AwaitAssert(() => Assert.Equal(0, actor.UnderlyingActor.RunsInFlight), TimeSpan.FromSeconds(5)); + Assert.Empty(siteLog.OfType("script")); + + // Flip live — same actor, no restart, no redeploy. + monitor.Set(Options(perRunScriptEvents: true)); + + actor.Tell(new ScriptCallRequest("Runner", null, 0, "corr-hot-2"), caller.Ref); + caller.ExpectMsg(TimeSpan.FromSeconds(10)); + AwaitAssert(() => Assert.Equal(2, siteLog.OfType("script").Count), TimeSpan.FromSeconds(5)); + } } /// diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunEventPolicyTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunEventPolicyTests.cs new file mode 100644 index 00000000..ef392bf9 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunEventPolicyTests.cs @@ -0,0 +1,84 @@ +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; + +/// +/// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md, +/// stage (b) test plan items 1–3): pure unit tests for +/// , isolated from any actor or DI +/// plumbing — the actor-level wiring (hot toggle, hosted-service registration) is covered by +/// ScriptRunLauncherParityTests. +/// +public class ScriptRunEventPolicyTests +{ + private static SiteRuntimeOptions Options( + bool perRunScriptEvents = false, string[]? perRunScriptEventScripts = null) + => new() + { + PerRunScriptEvents = perRunScriptEvents, + PerRunScriptEventScripts = (perRunScriptEventScripts ?? []).ToList() + }; + + [Fact] + public void DefaultOptions_EmitsNothing() + { + Assert.False(ScriptRunEventPolicy.ShouldEmitPerRun(Options(), "Inst1", "Runner")); + } + + [Fact] + public void GlobalSwitchOn_EmitsForEveryScript() + { + var options = Options(perRunScriptEvents: true); + + Assert.True(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst1", "Runner")); + Assert.True(ScriptRunEventPolicy.ShouldEmitPerRun(options, "AnyOtherInstance", "AnyOtherScript")); + } + + [Fact] + public void ExactPerScriptMatch_Emits() + { + var options = Options(perRunScriptEventScripts: ["Inst1/Runner"]); + + Assert.True(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst1", "Runner")); + } + + [Fact] + public void ExactPerScriptMatch_DoesNotMatchADifferentScriptOnTheSameInstance() + { + var options = Options(perRunScriptEventScripts: ["Inst1/Runner"]); + + Assert.False(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst1", "OtherScript")); + } + + [Fact] + public void ExactPerScriptMatch_DoesNotMatchTheSameScriptNameOnADifferentInstance() + { + var options = Options(perRunScriptEventScripts: ["Inst1/Runner"]); + + Assert.False(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst2", "Runner")); + } + + [Fact] + public void InstanceWildcard_EmitsForEveryScriptOnThatInstanceOnly() + { + var options = Options(perRunScriptEventScripts: ["Inst1/*"]); + + Assert.True(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst1", "Runner")); + Assert.True(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst1", "AnotherScript")); + Assert.False(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst2", "Runner")); + } + + [Fact] + public void NonMatchingScript_StaysSilent() + { + var options = Options(perRunScriptEventScripts: ["Inst1/Runner", "Inst2/*"]); + + Assert.False(ScriptRunEventPolicy.ShouldEmitPerRun(options, "Inst3", "Runner")); + } + + [Fact] + public void EmptyOptInList_StaysSilent() + { + Assert.False(ScriptRunEventPolicy.ShouldEmitPerRun(Options(), "Inst1", "Runner")); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs new file mode 100644 index 00000000..1019045e --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRunSummaryRecorderTests.cs @@ -0,0 +1,169 @@ +using System.Globalization; +using System.Text.Json; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.TestSupport; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; + +/// +/// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md, +/// stage (b) test plan item 5): in isolation — no +/// actor, no hosted service, just the accumulate/flush contract. +/// +public class ScriptRunSummaryRecorderTests +{ + [Fact] + public async Task ZeroActivity_FlushEmitsNoRow() + { + var recorder = new ScriptRunSummaryRecorder(); + var siteLog = new FakeSiteEventLogger(); + + var emitted = await recorder.FlushAsync(siteLog); + + Assert.False(emitted); + Assert.Empty(siteLog.Entries); + } + + [Fact] + public async Task MixedOutcomes_FlushEmitsOneRowWithCorrectTotals() + { + var recorder = new ScriptRunSummaryRecorder(); + + // Two scripts, mixed outcomes. + recorder.RecordStarted("Inst1", "A"); + recorder.RecordCompleted("Inst1", "A", 10); + recorder.RecordStarted("Inst1", "A"); + recorder.RecordCompleted("Inst1", "A", 30); + + recorder.RecordStarted("Inst1", "B"); + recorder.RecordFailed("Inst1", "B", 5); + + recorder.RecordTimedOut("Inst2", "C", 100); + + var siteLog = new FakeSiteEventLogger(); + var emitted = await recorder.FlushAsync(siteLog); + + Assert.True(emitted); + var rows = siteLog.OfType("script"); + Assert.Single(rows); + + var row = rows[0]; + Assert.Equal("Info", row.Severity); + Assert.Null(row.InstanceId); + Assert.Equal("ScriptRunSummary", row.Source); + + // Started: A x2 + B x1 = 3 (C never reaches RecordStarted — it is shed at dequeue, + // which is exactly why ranking uses Started+TimedOut, not Started alone). + // Completed: A x2 = 2. Failed: B x1 = 1. TimedOut: C x1 = 1. Scripts touched: A, B, C. + Assert.Equal("3 runs: 2 completed, 1 failed, 1 timed out across 3 scripts", row.Message); + + Assert.NotNull(row.Details); + using var doc = JsonDocument.Parse(row.Details!); + var scripts = doc.RootElement.GetProperty("scripts"); + Assert.Equal(3, scripts.GetArrayLength()); + } + + [Fact] + public async Task CountersReset_AfterFlush() + { + var recorder = new ScriptRunSummaryRecorder(); + recorder.RecordStarted("Inst1", "A"); + recorder.RecordCompleted("Inst1", "A", 1); + + var firstLog = new FakeSiteEventLogger(); + Assert.True(await recorder.FlushAsync(firstLog)); + + // Nothing recorded since the first flush — the second flush must be idle. + var secondLog = new FakeSiteEventLogger(); + var emitted = await recorder.FlushAsync(secondLog); + + Assert.False(emitted); + Assert.Empty(secondLog.Entries); + } + + [Fact] + public async Task MoreThanFiftyScripts_CapsBreakdownAndRollsUpTheRest() + { + var recorder = new ScriptRunSummaryRecorder(); + + // 60 distinct scripts, each with a distinct run count so ranking is deterministic: + // script "S00" gets 60 runs, "S01" gets 59, ... "S59" gets 1. + for (var i = 0; i < 60; i++) + { + var runs = 60 - i; + var scriptName = $"S{i:D2}"; + for (var r = 0; r < runs; r++) + { + recorder.RecordStarted("Inst1", scriptName); + recorder.RecordCompleted("Inst1", scriptName, 1); + } + } + + var siteLog = new FakeSiteEventLogger(); + var emitted = await recorder.FlushAsync(siteLog); + + Assert.True(emitted); + var row = siteLog.OfType("script").Single(); + Assert.Contains("60 scripts", row.Message); + + using var doc = JsonDocument.Parse(row.Details!); + var root = doc.RootElement; + var scripts = root.GetProperty("scripts"); + Assert.Equal(ScriptRunSummaryRecorder.TopScriptCap, scripts.GetArrayLength()); + + var others = root.GetProperty("others"); + Assert.Equal(10, others.GetProperty("scriptCount").GetInt64()); + // The ten lowest-run scripts (S50..S59) have run counts 10 down to 1 => sum 55. + Assert.Equal(55, others.GetProperty("started").GetInt64()); + + // The top entry must be the highest-run script (S00, 60 runs), not an arbitrary one. + var top = scripts[0]; + Assert.Equal("S00", top.GetProperty("scriptName").GetString()); + Assert.Equal(60, top.GetProperty("started").GetInt64()); + } + + [Fact] + public async Task ConcurrentIncrements_AreRaceFree() + { + var recorder = new ScriptRunSummaryRecorder(); + const int perTask = 500; + const int taskCount = 8; + + var tasks = Enumerable.Range(0, taskCount).Select(_ => Task.Run(() => + { + for (var i = 0; i < perTask; i++) + { + recorder.RecordStarted("Inst1", "Hot"); + recorder.RecordCompleted("Inst1", "Hot", 1); + } + })); + + await Task.WhenAll(tasks); + + var siteLog = new FakeSiteEventLogger(); + Assert.True(await recorder.FlushAsync(siteLog)); + + var row = siteLog.OfType("script").Single(); + var expectedTotal = (perTask * taskCount).ToString("N0", CultureInfo.InvariantCulture); + Assert.Contains($"{expectedTotal} runs", row.Message); + Assert.Contains($"{expectedTotal} completed", row.Message); + } + + [Fact] + public async Task DurationTracking_ReportsAverageAndMax() + { + var recorder = new ScriptRunSummaryRecorder(); + recorder.RecordStarted("Inst1", "A"); + recorder.RecordCompleted("Inst1", "A", 10); + recorder.RecordStarted("Inst1", "A"); + recorder.RecordCompleted("Inst1", "A", 30); + + var siteLog = new FakeSiteEventLogger(); + await recorder.FlushAsync(siteLog); + + using var doc = JsonDocument.Parse(siteLog.OfType("script").Single().Details!); + var script = doc.RootElement.GetProperty("scripts")[0]; + Assert.Equal(20, script.GetProperty("avgDurationMs").GetInt64()); + Assert.Equal(30, script.GetProperty("maxDurationMs").GetInt64()); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/FakeSiteEventLogger.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/FakeSiteEventLogger.cs index 7617fe14..dc47bfd1 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/FakeSiteEventLogger.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/FakeSiteEventLogger.cs @@ -1,6 +1,8 @@ using System.Collections.Concurrent; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Options; using ZB.MOM.WW.ScadaBridge.SiteEventLogging; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.TestSupport; @@ -59,16 +61,34 @@ public sealed class FakeSiteEventLogger : ISiteEventLogger /// don't throw before they reach the logging hot path. /// /// -public sealed class SingleServiceProvider(ISiteEventLogger logger) +/// The event logger to resolve for . +/// +/// WP3.2: optional for +/// — resolves for the hot-toggle tests; null (the default) exercises the launcher's +/// constructor-passed-options fallback, matching every pre-WP3.2 caller of this class. +/// +/// +/// WP3.2: optional — resolves so a test can assert on +/// the aggregate counters a run produced; null (the default) exercises the launcher's +/// null-safe skip path. +/// +public sealed class SingleServiceProvider( + ISiteEventLogger logger, + IOptionsMonitor? optionsMonitor = null, + ScriptRunSummaryRecorder? summaryRecorder = null) : IServiceProvider, IServiceScopeFactory, IServiceScope { private readonly ISiteEventLogger _logger = logger; + private readonly IOptionsMonitor? _optionsMonitor = optionsMonitor; + private readonly ScriptRunSummaryRecorder? _summaryRecorder = summaryRecorder; /// public object? GetService(Type serviceType) { if (serviceType == typeof(ISiteEventLogger)) return _logger; if (serviceType == typeof(IServiceScopeFactory)) return this; + if (serviceType == typeof(IOptionsMonitor)) return _optionsMonitor; + if (serviceType == typeof(ScriptRunSummaryRecorder)) return _summaryRecorder; return null; } diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/TestOptionsMonitor.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/TestOptionsMonitor.cs new file mode 100644 index 00000000..ac909e78 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/TestSupport/TestOptionsMonitor.cs @@ -0,0 +1,29 @@ +using Microsoft.Extensions.Options; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.TestSupport; + +/// +/// Minimal test double with a mutable +/// so a test can flip a value mid-run and assert the NEXT read observes it +/// — used by the WP3.2 hot-toggle tests +/// (SiteRuntimeOptions.PerRunScriptEvents/PerRunScriptEventScripts are read via +/// IOptionsMonitor.CurrentValue per run specifically so they don't need a restart). +/// Avoids depending on Microsoft.Extensions.Configuration's reload-token plumbing, +/// which is awkward to drive deterministically from xUnit. +/// +public sealed class TestOptionsMonitor(T initial) : IOptionsMonitor +{ + private T _current = initial; + + /// + public T CurrentValue => _current; + + /// + public T Get(string? name) => _current; + + /// + public IDisposable? OnChange(Action listener) => null; + + /// Replaces the current value, observed by the next read. + public void Set(T value) => _current = value; +}