perf(sitelog): sampled per-run events; interval run summaries; site_events replication policy pinned

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<SiteRuntimeOptions> 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).
This commit is contained in:
Joseph Doherty
2026-08-14 22:56:08 -04:00
parent 799fd041ec
commit c254d0740e
15 changed files with 922 additions and 27 deletions
@@ -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<ScriptCallResult>(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<ScriptCallResult>(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<ScriptCallResult>(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<SiteRuntimeOptions>(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<ScriptCallResult>(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<ScriptCallResult>(TimeSpan.FromSeconds(10));
AwaitAssert(() => Assert.Equal(2, siteLog.OfType("script").Count), TimeSpan.FromSeconds(5));
}
}
/// <summary>
@@ -0,0 +1,84 @@
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts;
/// <summary>
/// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md,
/// stage (b) test plan items 13): pure unit tests for
/// <see cref="ScriptRunEventPolicy.ShouldEmitPerRun"/>, isolated from any actor or DI
/// plumbing — the actor-level wiring (hot toggle, hosted-service registration) is covered by
/// <c>ScriptRunLauncherParityTests</c>.
/// </summary>
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"));
}
}
@@ -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;
/// <summary>
/// WP3.2 (site_events volume policy — docs/plans/2026-08-15-site-events-policy-design.md,
/// stage (b) test plan item 5): <see cref="ScriptRunSummaryRecorder"/> in isolation — no
/// actor, no hosted service, just the accumulate/flush contract.
/// </summary>
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());
}
}
@@ -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.
/// </para>
/// </summary>
public sealed class SingleServiceProvider(ISiteEventLogger logger)
/// <param name="logger">The event logger to resolve for <see cref="ISiteEventLogger"/>.</param>
/// <param name="optionsMonitor">
/// WP3.2: optional <see cref="IOptionsMonitor{TOptions}"/> for <see cref="SiteRuntimeOptions"/>
/// — 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.
/// </param>
/// <param name="summaryRecorder">
/// WP3.2: optional <see cref="ScriptRunSummaryRecorder"/> — resolves so a test can assert on
/// the aggregate counters a run produced; null (the default) exercises the launcher's
/// null-safe skip path.
/// </param>
public sealed class SingleServiceProvider(
ISiteEventLogger logger,
IOptionsMonitor<SiteRuntimeOptions>? optionsMonitor = null,
ScriptRunSummaryRecorder? summaryRecorder = null)
: IServiceProvider, IServiceScopeFactory, IServiceScope
{
private readonly ISiteEventLogger _logger = logger;
private readonly IOptionsMonitor<SiteRuntimeOptions>? _optionsMonitor = optionsMonitor;
private readonly ScriptRunSummaryRecorder? _summaryRecorder = summaryRecorder;
/// <inheritdoc />
public object? GetService(Type serviceType)
{
if (serviceType == typeof(ISiteEventLogger)) return _logger;
if (serviceType == typeof(IServiceScopeFactory)) return this;
if (serviceType == typeof(IOptionsMonitor<SiteRuntimeOptions>)) return _optionsMonitor;
if (serviceType == typeof(ScriptRunSummaryRecorder)) return _summaryRecorder;
return null;
}
@@ -0,0 +1,29 @@
using Microsoft.Extensions.Options;
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.TestSupport;
/// <summary>
/// Minimal <see cref="IOptionsMonitor{TOptions}"/> test double with a mutable
/// <see cref="Set"/> so a test can flip a value mid-run and assert the NEXT read observes it
/// — used by the WP3.2 hot-toggle tests
/// (<c>SiteRuntimeOptions.PerRunScriptEvents</c>/<c>PerRunScriptEventScripts</c> are read via
/// <c>IOptionsMonitor.CurrentValue</c> per run specifically so they don't need a restart).
/// Avoids depending on <c>Microsoft.Extensions.Configuration</c>'s reload-token plumbing,
/// which is awkward to drive deterministically from xUnit.
/// </summary>
public sealed class TestOptionsMonitor<T>(T initial) : IOptionsMonitor<T>
{
private T _current = initial;
/// <inheritdoc />
public T CurrentValue => _current;
/// <inheritdoc />
public T Get(string? name) => _current;
/// <inheritdoc />
public IDisposable? OnChange(Action<T, string?> listener) => null;
/// <summary>Replaces the current value, observed by the next <see cref="CurrentValue"/> read.</summary>
public void Set(T value) => _current = value;
}