Joseph Doherty
6cbf763719
- R05:1/12 ScriptedAlarmEngine: _valueCache is cleared in LoadAsync (it is re-seeded for the referenced paths) so retired tags no longer accrete across deploys; OnUpstreamChange no longer writes the cache after Dispose. - R05:3 ScriptedAlarmEngine.Dispose drains in-flight work for at most 5 s (DisposeDrainTimeout), then cancels it through a shutdown token every DrainDirtyAsync/ShelvingCheckAsync now runs on, logs a Warning and gives one second of grace — a stalled IAlarmStateStore.SaveAsync can no longer hang host shutdown. A save that completes inside the bound is still drained (positive control test). - R05:6 ScriptedAlarmSource logs a throwing OnAlarmEvent subscriber at Warning (naming the alarm) instead of swallowing it. - R05:7 LocalDbStoreAndForwardSink keeps a cached dead-letter counter in step with every dead-letter/revive/purge path and resyncs it with the queued counter on the same cadence; GetStatus no longer runs a COUNT(*) scan. - R05:9 ScriptLogRateLimiter (20 per source per minute, fixed window, one summary entry naming the dropped count when the window rolls) behind ScriptLogTopicSink (key = script|vtag|alarm) and ScriptLogCompanionSink (key = script name). Refs #734 Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT
91 lines
4.2 KiB
C#
91 lines
4.2 KiB
C#
using Serilog;
|
|
using Serilog.Core;
|
|
using Serilog.Events;
|
|
|
|
namespace ZB.MOM.WW.OtOpcUa.Core.Scripting;
|
|
|
|
/// <summary>
|
|
/// Serilog sink that mirrors script log events at <see cref="LogEventLevel.Error"/>
|
|
/// or higher to a companion logger (typically the main <c>opcua-*.log</c>) at
|
|
/// <see cref="LogEventLevel.Warning"/>. Lets operators see script errors in the
|
|
/// primary server log without drowning it in Debug/Info/Warning noise from scripts.
|
|
/// </summary>
|
|
/// <remarks>
|
|
/// <para>
|
|
/// Registered alongside the dedicated <c>scripts-*.log</c> rolling file sink in
|
|
/// the root script-logger configuration — events below Error land only in the
|
|
/// scripts file; Error/Fatal events land in both the scripts file (at original
|
|
/// level) and the main log (downgraded to Warning since the main log's audience
|
|
/// is server operators, not script authors).
|
|
/// </para>
|
|
/// <para>
|
|
/// The forwarded message preserves the <c>ScriptName</c> property so operators
|
|
/// reading the main log can tell which script raised the error at a glance.
|
|
/// Original exception (if any) is attached so the main log's diagnostics keep
|
|
/// the full stack trace.
|
|
/// </para>
|
|
/// <para>
|
|
/// <b>Rate-limited per script.</b> A predicate that throws on every push would otherwise mirror
|
|
/// one Warning per push into the main log; a <see cref="ScriptLogRateLimiter"/> keyed by script
|
|
/// name admits 20 per minute and mirrors one summary line for the rest when the window rolls. The
|
|
/// scripts-*.log file sink is unaffected and keeps the full stream.
|
|
/// </para>
|
|
/// </remarks>
|
|
public sealed class ScriptLogCompanionSink : ILogEventSink
|
|
{
|
|
private readonly ILogger _mainLogger;
|
|
private readonly LogEventLevel _minMirrorLevel;
|
|
private readonly ScriptLogRateLimiter _limiter;
|
|
|
|
/// <summary>Initializes a new instance of the ScriptLogCompanionSink.</summary>
|
|
/// <param name="mainLogger">The companion logger to mirror events to.</param>
|
|
/// <param name="minMirrorLevel">The minimum log level to mirror (default: Error).</param>
|
|
/// <param name="limiter">Per-script rate limiter; null ⇒ the default 20 per minute.</param>
|
|
public ScriptLogCompanionSink(ILogger mainLogger, LogEventLevel minMirrorLevel = LogEventLevel.Error,
|
|
ScriptLogRateLimiter? limiter = null)
|
|
{
|
|
_mainLogger = mainLogger ?? throw new ArgumentNullException(nameof(mainLogger));
|
|
_minMirrorLevel = minMirrorLevel;
|
|
_limiter = limiter ?? new ScriptLogRateLimiter();
|
|
}
|
|
|
|
/// <summary>Emits a log event to the companion logger if it meets the minimum level and the script is within its per-minute budget.</summary>
|
|
/// <param name="logEvent">The log event to emit.</param>
|
|
public void Emit(LogEvent logEvent)
|
|
{
|
|
if (logEvent is null) return;
|
|
if (logEvent.Level < _minMirrorLevel) return;
|
|
|
|
var scriptName = "unknown";
|
|
if ((logEvent.Properties.TryGetValue(ScriptLoggerFactory.ScriptNameProperty, out var prop)
|
|
|| logEvent.Properties.TryGetValue(ScriptLoggerFactory.ScriptIdProperty, out prop))
|
|
&& prop is ScalarValue sv && sv.Value is string s)
|
|
{
|
|
scriptName = s;
|
|
}
|
|
|
|
var admission = _limiter.Admit(scriptName);
|
|
if (admission.SuppressedInPreviousWindow > 0)
|
|
{
|
|
_mainLogger.Warning(
|
|
"[Script] {ScriptName}: {SuppressedCount} further script error(s) were suppressed in the previous {WindowSeconds:F0} s; see scripts-*.log",
|
|
scriptName, admission.SuppressedInPreviousWindow, _limiter.Window.TotalSeconds);
|
|
}
|
|
if (!admission.Admitted) return;
|
|
|
|
var rendered = logEvent.RenderMessage();
|
|
if (logEvent.Exception is not null)
|
|
{
|
|
_mainLogger.Warning(logEvent.Exception,
|
|
"[Script] {ScriptName} emitted {OriginalLevel}: {ScriptMessage}",
|
|
scriptName, logEvent.Level, rendered);
|
|
}
|
|
else
|
|
{
|
|
_mainLogger.Warning(
|
|
"[Script] {ScriptName} emitted {OriginalLevel}: {ScriptMessage}",
|
|
scriptName, logEvent.Level, rendered);
|
|
}
|
|
}
|
|
}
|