using Serilog; using Serilog.Core; using Serilog.Events; using Shouldly; using Xunit; using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging; namespace ZB.MOM.WW.OtOpcUa.Core.Scripting.Tests; /// /// Per-source rate limit on the script-log fan-out (review R05:9 / R02:P6): a script that logs — or /// fails — on every evaluation of a 1 Hz input used to put one entry per second per script onto the /// cluster bus and the main log. The limiter admits the first 20 entries per source per minute, drops /// the rest, and surfaces one summary line (with the dropped count) when the next entry arrives after /// the window rolled — so nothing is silently lost, and a chatty script cannot shed everyone else's /// entries out of the bounded telemetry channels. /// [Trait("Category", "Unit")] public sealed class ScriptLogRateLimiterTests { private sealed class Clock { public DateTime Now = new(2026, 1, 1, 12, 0, 0, DateTimeKind.Utc); public void Advance(TimeSpan by) => Now += by; } [Fact] public void Admits_the_first_N_per_window_then_suppresses_and_summarises_once_the_window_rolls() { var clock = new Clock(); var limiter = new ScriptLogRateLimiter(limitPerWindow: 3, window: TimeSpan.FromMinutes(1), clock: () => clock.Now); limiter.Admit("s1").Admitted.ShouldBeTrue(); limiter.Admit("s1").Admitted.ShouldBeTrue(); limiter.Admit("s1").Admitted.ShouldBeTrue(); limiter.Admit("s1").Admitted.ShouldBeFalse(); limiter.Admit("s1").Admitted.ShouldBeFalse(); limiter.Admit("s1").SuppressedInPreviousWindow.ShouldBe(0, "no summary until the window rolls"); clock.Advance(TimeSpan.FromMinutes(1)); var first = limiter.Admit("s1"); first.Admitted.ShouldBeTrue("a fresh window admits again"); first.SuppressedInPreviousWindow.ShouldBe(3, "the caller emits one summary for the three dropped entries"); limiter.Admit("s1").SuppressedInPreviousWindow.ShouldBe(0, "the summary is reported exactly once"); } [Fact] public void Sources_are_independent() { var limiter = new ScriptLogRateLimiter(limitPerWindow: 1); limiter.Admit("a").Admitted.ShouldBeTrue(); limiter.Admit("a").Admitted.ShouldBeFalse(); limiter.Admit("b").Admitted.ShouldBeTrue("a chatty source must not shed another source's entries"); } [Fact] public void Defaults_are_20_per_minute() { ScriptLogRateLimiter.DefaultLimitPerWindow.ShouldBe(20); ScriptLogRateLimiter.DefaultWindow.ShouldBe(TimeSpan.FromMinutes(1)); var limiter = new ScriptLogRateLimiter(); limiter.LimitPerWindow.ShouldBe(20); new ScriptLogRateLimiter(limitPerWindow: 3).LimitPerWindow.ShouldBe(3); new ScriptLogRateLimiter(limitPerWindow: 0).LimitPerWindow.ShouldBe(1, "values below 1 are treated as 1"); for (var i = 0; i < 20; i++) limiter.Admit("s").Admitted.ShouldBeTrue(); limiter.Admit("s").Admitted.ShouldBeFalse(); } // ── the two sinks ──────────────────────────────────────────────────────────────────────── private sealed class FakePublisher : IScriptLogPublisher { public List Published { get; } = []; public void Publish(ScriptLogEntry entry) => Published.Add(entry); } private static LogEvent Evt(LogEventLevel level, string template, params (string Key, string Val)[] props) { var tmpl = new Serilog.Parsing.MessageTemplateParser().Parse(template); var logProps = props.Select(p => new LogEventProperty(p.Key, new ScalarValue(p.Val))); return new LogEvent(DateTimeOffset.UtcNow, level, exception: null, tmpl, logProps); } [Fact] public void Topic_sink_rate_limits_per_source_and_publishes_a_summary_entry() { var clock = new Clock(); var publisher = new FakePublisher(); var sink = new ScriptLogTopicSink(publisher, LogEventLevel.Information, new ScriptLogRateLimiter(limitPerWindow: 2, clock: () => clock.Now)); for (var i = 0; i < 5; i++) sink.Emit(Evt(LogEventLevel.Warning, "chatty", (ScriptLoggerFactory.ScriptIdProperty, "S1"), (ScriptLoggerFactory.VirtualTagIdProperty, "V1"))); sink.Emit(Evt(LogEventLevel.Warning, "other", (ScriptLoggerFactory.ScriptIdProperty, "S2"))); publisher.Published.Count(e => e.ScriptId == "S1").ShouldBe(2, "the limit is per source"); publisher.Published.Count(e => e.ScriptId == "S2").ShouldBe(1, "another source is unaffected"); clock.Advance(TimeSpan.FromMinutes(1)); sink.Emit(Evt(LogEventLevel.Warning, "chatty again", (ScriptLoggerFactory.ScriptIdProperty, "S1"), (ScriptLoggerFactory.VirtualTagIdProperty, "V1"))); var s1 = publisher.Published.Where(e => e.ScriptId == "S1").ToList(); s1.Count.ShouldBe(4, "2 admitted + 1 summary + 1 admitted in the new window"); var summary = s1[2]; summary.Message.ShouldContain("3"); summary.Message.ShouldContain("suppressed"); summary.Message.ShouldContain("limit 2/window", Case.Sensitive, "the summary names the CONFIGURED limit, not the default"); summary.VirtualTagId.ShouldBe("V1", "the summary carries the source's identity so the page attributes it"); summary.Level.ShouldBe("Warning"); s1[3].Message.ShouldBe("chatty again"); } private sealed class CapturingSink : ILogEventSink { public List Events { get; } = []; public void Emit(LogEvent logEvent) => Events.Add(logEvent); } [Fact] public void Companion_sink_rate_limits_per_script_and_mirrors_a_summary_line() { var clock = new Clock(); var main = new CapturingSink(); var mainLogger = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(main).CreateLogger(); var sink = new ScriptLogCompanionSink(mainLogger, LogEventLevel.Error, new ScriptLogRateLimiter(limitPerWindow: 2, clock: () => clock.Now)); for (var i = 0; i < 5; i++) sink.Emit(Evt(LogEventLevel.Error, "boom", (ScriptLoggerFactory.ScriptNameProperty, "HighTemp"))); main.Events.Count.ShouldBe(2); clock.Advance(TimeSpan.FromMinutes(1)); sink.Emit(Evt(LogEventLevel.Error, "boom", (ScriptLoggerFactory.ScriptNameProperty, "HighTemp"))); main.Events.Count.ShouldBe(4); var summary = main.Events[2].RenderMessage(); summary.ShouldContain("HighTemp"); summary.ShouldContain("3"); summary.ShouldContain("suppressed"); } }