fix(site-runtime): rate-limit shed Warning logs per script/alarm (review 2026-10-21 01/SR-P6)

This commit is contained in:
Joseph Doherty
2026-10-22 08:29:50 -04:00
parent 7541a38762
commit 4ff26a0614
3 changed files with 58 additions and 6 deletions
@@ -73,6 +73,7 @@ public class AlarmActor : ReceiveActor
/// always counted; the event is rate-limited to one per alarm per minute.
/// </summary>
private DateTimeOffset _lastShedEventUtc = DateTimeOffset.MinValue;
private int _shedSuppressed;
/// <summary>Rate limit for the shed site event (the counter still counts every shed).</summary>
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);
}
@@ -86,6 +86,7 @@ public class ScriptActor : ReceiveActor, IWithTimers
/// <c>site_events</c>.
/// </summary>
private DateTimeOffset _lastShedEventUtc = DateTimeOffset.MinValue;
private int _shedSuppressed;
/// <summary>Rate limit for the shed site event (the counter still counts every shed).</summary>
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<ISiteEventLogger>()?.LogEventAsync(
"script", "Warning", _instanceName, $"ScriptActor:{_scriptName}", message);
}
@@ -81,6 +81,50 @@ public class ScriptRunShedTests : TestKit, IDisposable
StuckScriptGraceMs = 120_000
};
/// <summary>Repeated sheds log one Warning per interval, not one per shed (review 2026-10-21 01/SR-P6).</summary>
[Fact]
public void RepeatedSheds_LogOneWarningPerInterval()
{
var logger = new CountingLogger<ScriptActor>();
var instance = CreateTestProbe().Ref;
var actor = ActorOfAsTestActorRef<ScriptActor>(
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<ScriptCallResult>(TimeSpan.FromSeconds(10));
}
Assert.Equal(1, logger.Count(l => l == Microsoft.Extensions.Logging.LogLevel.Warning, "run shed"));
}
private sealed class CountingLogger<T> : Microsoft.Extensions.Logging.ILogger<T>
{
private readonly List<(Microsoft.Extensions.Logging.LogLevel Level, string Text)> _entries = new();
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
public bool IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel) => true;
public void Log<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId,
TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
lock (_entries) _entries.Add((logLevel, formatter(state, exception)));
}
public int Count(Func<Microsoft.Extensions.Logging.LogLevel, bool> level, string contains)
{
lock (_entries) return _entries.Count(e => level(e.Level) && e.Text.Contains(contains));
}
}
/// <summary>Verifies that a fifth concurrent run is shed, counted and reported as a site event once, and the caller is answered with an error.</summary>
[Fact]
public void FifthConcurrentRun_IsShed_Counted_EventedOnce_AndAnsweredWithAnError()