Joseph Doherty
5ef27fd9a3
Adds four instruments on the already-allow-listed ZB.MOM.WW.ScadaBridge meter:
scadabridge.deployments.failed{reason}, scadabridge.store_and_forward.activity{action,category},
scadabridge.site.script.runs{outcome} + scadabridge.site.script.duration{outcome} (ms),
scadabridge.site.data_connections.transitions{state}. Queue depth, DCL connection state and
deploy-applied already existed. No new Meter, so ZbTelemetryOptions.Meters needs no change.
Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV
277 lines
12 KiB
C#
277 lines
12 KiB
C#
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>
|
|
/// Site-events volume policy (docs/plans/2026-08-15-site-events-policy-design.md):
|
|
/// <see cref="ScriptRunSummaryRecorder"/> in isolation — no
|
|
/// actor, no hosted service, just the accumulate/flush contract.
|
|
/// </summary>
|
|
public class ScriptRunSummaryRecorderTests
|
|
{
|
|
/// <summary>Verifies each finished run emits the script runs counter and duration histogram with its outcome (ScadaBridge#81).</summary>
|
|
[Fact]
|
|
public void FinishedRuns_EmitRunCounterAndDurationHistogram_TaggedByOutcome()
|
|
{
|
|
// MeterListener callbacks run synchronously on the emitting thread, so filtering on the
|
|
// test thread isolates this test from other tests emitting on the same process-wide meter.
|
|
var tid = Environment.CurrentManagedThreadId;
|
|
var runs = new List<string?>();
|
|
var durations = new List<(string? Outcome, long Ms)>();
|
|
using var listener = new System.Diagnostics.Metrics.MeterListener
|
|
{
|
|
InstrumentPublished = (i, l) =>
|
|
{
|
|
if (i.Meter.Name == Commons.Observability.ScadaBridgeTelemetry.MeterName
|
|
&& (i.Name == "scadabridge.site.script.runs" || i.Name == "scadabridge.site.script.duration"))
|
|
l.EnableMeasurementEvents(i);
|
|
}
|
|
};
|
|
static string? Outcome(ReadOnlySpan<KeyValuePair<string, object?>> tags)
|
|
{
|
|
foreach (var t in tags) if (t.Key == "outcome") return t.Value as string;
|
|
return null;
|
|
}
|
|
listener.SetMeasurementEventCallback<long>((inst, m, tags, _) =>
|
|
{
|
|
if (Environment.CurrentManagedThreadId != tid) return;
|
|
if (inst.Name == "scadabridge.site.script.runs") runs.Add(Outcome(tags));
|
|
else durations.Add((Outcome(tags), m));
|
|
});
|
|
listener.Start();
|
|
|
|
var recorder = new ScriptRunSummaryRecorder();
|
|
recorder.RecordCompleted("i", "s", 10);
|
|
recorder.RecordFailed("i", "s", 20);
|
|
recorder.RecordTimedOut("i", "s", 30);
|
|
|
|
Assert.Equal(new string?[] { "completed", "failed", "timed_out" }, runs);
|
|
Assert.Equal(
|
|
new (string?, long)[] { ("completed", 10), ("failed", 20), ("timed_out", 30) },
|
|
durations);
|
|
}
|
|
|
|
/// <summary>Verifies that flushing with no activity emits no row.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[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);
|
|
}
|
|
|
|
/// <summary>Verifies that flushing mixed outcomes emits one row with the correct totals.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[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());
|
|
}
|
|
|
|
/// <summary>Verifies that the counters reset after a flush.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[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);
|
|
}
|
|
|
|
/// <summary>Verifies that more than fifty scripts cap the breakdown and roll up the remainder.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[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());
|
|
}
|
|
|
|
/// <summary>Verifies that concurrent increments are race-free.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[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);
|
|
}
|
|
|
|
/// <summary>Verifies that a run spanning a flush boundary still reports its completion in the next window.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[Fact]
|
|
public async Task RunSpanningAFlushBoundary_StillReportsItsCompletionInTheNextWindow()
|
|
{
|
|
// A long run starts in window N and finishes in window N+1. Its completion is recorded
|
|
// against a FRESH counters object whose Started is 0 — so a flush filter keyed on
|
|
// Started/Failed/TimedOut alone would discard it, and the completion (plus its
|
|
// duration) would appear in NO summary row at all: window N reports a run that started
|
|
// and never finished, window N+1 reports nothing.
|
|
var recorder = new ScriptRunSummaryRecorder();
|
|
recorder.RecordStarted("Inst1", "Slow");
|
|
|
|
var firstLog = new FakeSiteEventLogger();
|
|
Assert.True(await recorder.FlushAsync(firstLog));
|
|
Assert.Equal("1 runs: 0 completed, 0 failed, 0 timed out across 1 scripts",
|
|
firstLog.OfType("script").Single().Message);
|
|
|
|
// …the run finishes after that flush.
|
|
recorder.RecordCompleted("Inst1", "Slow", 42);
|
|
|
|
var secondLog = new FakeSiteEventLogger();
|
|
Assert.True(await recorder.FlushAsync(secondLog));
|
|
|
|
var row = secondLog.OfType("script").Single();
|
|
Assert.Equal("0 runs: 1 completed, 0 failed, 0 timed out across 1 scripts", row.Message);
|
|
|
|
// The duration is carried too, so the completion is not merely counted.
|
|
using var doc = JsonDocument.Parse(row.Details!);
|
|
var script = doc.RootElement.GetProperty("scripts")[0];
|
|
Assert.Equal("Slow", script.GetProperty("scriptName").GetString());
|
|
Assert.Equal(0, script.GetProperty("started").GetInt64());
|
|
Assert.Equal(1, script.GetProperty("completed").GetInt64());
|
|
Assert.Equal(42, script.GetProperty("maxDurationMs").GetInt64());
|
|
}
|
|
|
|
/// <summary>Verifies that a completion-only entry does not undo idle flush suppression.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[Fact]
|
|
public async Task CompletionOnlyEntry_DoesNotResurrectTheIdleFlushSuppression()
|
|
{
|
|
// The Completed>0 admission must not weaken "an idle interval emits nothing": a window
|
|
// in which literally nothing was recorded still has zero entries to admit.
|
|
var recorder = new ScriptRunSummaryRecorder();
|
|
recorder.RecordStarted("Inst1", "A");
|
|
recorder.RecordCompleted("Inst1", "A", 1);
|
|
Assert.True(await recorder.FlushAsync(new FakeSiteEventLogger()));
|
|
|
|
var idleLog = new FakeSiteEventLogger();
|
|
Assert.False(await recorder.FlushAsync(idleLog));
|
|
Assert.Empty(idleLog.Entries);
|
|
}
|
|
|
|
/// <summary>Verifies that duration tracking reports the average and maximum.</summary>
|
|
/// <returns>A task that represents the asynchronous operation.</returns>
|
|
[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());
|
|
}
|
|
}
|