ef2eebe6b6
- ScriptLogRateLimiter.LimitPerWindow. The ScriptLogTopicSink and VirtualTagActor summaries now print the configured limit, not DefaultLimitPerWindow. Tests assert "limit N/window" for a non-default N. - CalculationDriver.Dispose cancels, then takes _evalGate (bounded 2 s) and disposes the gate and _evalCts. The pump and timer ticks enter the gate through TryEnterEvalGateAsync, which stops cleanly once the driver is disposed. Test: Dispose with a 6 s runaway run in flight returns promptly, disposes both, and a late trigger is harmless. - ScriptedAlarmEngine captures _shutdownToken once and disposes _shutdownCts in Dispose when every drained task has completed. A task stuck past the grace leaves the CTS to the GC. Lifecycle tests assert the disposal. - DraftValidator: CalculationNoEffectiveTrigger is skipped for a change-triggered tag whose scriptId does not resolve. That case is already CalculationScriptMissing or CalculationScriptNotFound, and there are no reads to count. Both existing tests now assert the absence (red before the change). - docs/VirtualTags.md: System.Threading is denied as a whole namespace, with an allow-list; the type list is now accurate (Unsafe, RuntimeHelpers, and the ForbiddenMembers on System.Type); the resource limits section covers the run guard and the allocation budget. docs/ScriptEditor.md: accurate deny-list and a new "Runtime safety" section covering timeout, refusal, quarantine after 3 timeouts, allocation budget, lifting, and rate-limit summaries that appear only on the source's next entry after a burst then quiet. Refs #734 Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT
142 lines
6.6 KiB
C#
142 lines
6.6 KiB
C#
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;
|
|
|
|
/// <summary>
|
|
/// 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.
|
|
/// </summary>
|
|
[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<ScriptLogEntry> 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<LogEvent> 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");
|
|
}
|
|
}
|