From 4ff26a0614337f1058467b346f10effa6eebe945 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Thu, 22 Oct 2026 08:29:50 -0400 Subject: [PATCH] fix(site-runtime): rate-limit shed Warning logs per script/alarm (review 2026-10-21 01/SR-P6) --- .../Actors/AlarmActor.cs | 8 +++- .../Actors/ScriptActor.cs | 12 +++-- .../Actors/ScriptRunShedTests.cs | 44 +++++++++++++++++++ 3 files changed, 58 insertions(+), 6 deletions(-) diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs index 00399854..1f1c4215 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/AlarmActor.cs @@ -73,6 +73,7 @@ public class AlarmActor : ReceiveActor /// always counted; the event is rate-limited to one per alarm per minute. /// private DateTimeOffset _lastShedEventUtc = DateTimeOffset.MinValue; + private int _shedSuppressed; /// Rate limit for the shed site event (the counter still counts every shed). private static readonly TimeSpan ShedEventInterval = TimeSpan.FromMinutes(1); @@ -864,12 +865,15 @@ public class AlarmActor : ReceiveActor var message = $"Alarm on-trigger script for '{_alarmName}' on instance '{_instanceName}': run shed — " + $"{_runsInFlight} runs already in flight (cap {_options.MaxConcurrentRunsPerScript})."; - _logger.LogWarning("{Message}", message); - + // Log + site event share one rate limit (review 2026-10-21 01/SR-P6); the counter above + // counts every shed and the log line reports how many occurred since the last one. + _shedSuppressed++; var now = DateTimeOffset.UtcNow; if (now - _lastShedEventUtc >= ShedEventInterval) { _lastShedEventUtc = now; + _logger.LogWarning("{Message} ({Shed} shed(s) since the last report)", message, _shedSuppressed); + _shedSuppressed = 0; _ = _siteEventLogger?.LogEventAsync( "script", "Warning", _instanceName, $"AlarmActor:{_alarmName}", message); } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs index 4ca5689d..67c3a4d0 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Actors/ScriptActor.cs @@ -86,6 +86,7 @@ public class ScriptActor : ReceiveActor, IWithTimers /// site_events. /// private DateTimeOffset _lastShedEventUtc = DateTimeOffset.MinValue; + private int _shedSuppressed; /// Rate limit for the shed site event (the counter still counts every shed). private static readonly TimeSpan ShedEventInterval = TimeSpan.FromMinutes(1); @@ -678,14 +679,17 @@ public class ScriptActor : ReceiveActor, IWithTimers var message = $"Script '{_scriptName}' on instance '{_instanceName}': run shed — " + $"{_runsInFlight} runs already in flight (cap {_options.MaxConcurrentRunsPerScript})."; - _logger.LogWarning("{Message}", message); - - // Rate-limited to one event per script per minute: the counter above still counts - // every shed, but a hot trigger against a saturated cap must not flood site_events. + // Rate-limited to one log line + one event per script per minute: the counter above + // still counts every shed, but a hot trigger against a saturated cap must not flood + // site_events or the node log (review 2026-10-21 01/SR-P6). The first shed logs at once; + // later lines carry the number of sheds suppressed since the previous one. + _shedSuppressed++; var now = DateTimeOffset.UtcNow; if (now - _lastShedEventUtc >= ShedEventInterval) { _lastShedEventUtc = now; + _logger.LogWarning("{Message} ({Shed} shed(s) since the last report)", message, _shedSuppressed); + _shedSuppressed = 0; _ = _serviceProvider?.GetService()?.LogEventAsync( "script", "Warning", _instanceName, $"ScriptActor:{_scriptName}", message); } diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs index 2eefc0ba..6c2b110c 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Actors/ScriptRunShedTests.cs @@ -81,6 +81,50 @@ public class ScriptRunShedTests : TestKit, IDisposable StuckScriptGraceMs = 120_000 }; + /// Repeated sheds log one Warning per interval, not one per shed (review 2026-10-21 01/SR-P6). + [Fact] + public void RepeatedSheds_LogOneWarningPerInterval() + { + var logger = new CountingLogger(); + var instance = CreateTestProbe().Ref; + var actor = ActorOfAsTestActorRef( + Props.Create(() => new ScriptActor( + "Hot", "Inst1", instance, BlockingScript(), + new ResolvedScript { CanonicalName = "Hot", TriggerType = "Call" }, + _sharedLibrary, Options(), logger, + null, null, new SiteHealthCollector(), new SingleServiceProvider(new FakeSiteEventLogger()), _scheduler, null)), + "shedlog-" + Guid.NewGuid().ToString("N")); + + for (var i = 0; i < 4; i++) + actor.Tell(new ScriptCallRequest("Hot", null, 0, $"corr-{i}"), ActorRefs.NoSender); + AwaitAssert(() => Assert.Equal(4, actor.UnderlyingActor.RunsInFlight), TimeSpan.FromSeconds(15)); + + var caller = CreateTestProbe(); + for (var i = 0; i < 5; i++) + { + actor.Tell(new ScriptCallRequest("Hot", null, 0, $"shed-{i}"), caller.Ref); + caller.ExpectMsg(TimeSpan.FromSeconds(10)); + } + + Assert.Equal(1, logger.Count(l => l == Microsoft.Extensions.Logging.LogLevel.Warning, "run shed")); + } + + private sealed class CountingLogger : Microsoft.Extensions.Logging.ILogger + { + private readonly List<(Microsoft.Extensions.Logging.LogLevel Level, string Text)> _entries = new(); + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel) => true; + public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, + TState state, Exception? exception, Func formatter) + { + lock (_entries) _entries.Add((logLevel, formatter(state, exception))); + } + public int Count(Func level, string contains) + { + lock (_entries) return _entries.Count(e => level(e.Level) && e.Text.Contains(contains)); + } + } + /// Verifies that a fifth concurrent run is shed, counted and reported as a site event once, and the caller is answered with an error. [Fact] public void FifthConcurrentRun_IsShed_Counted_EventedOnce_AndAnsweredWithAnError()