Merge wt/step-logs-t4: Task 4 ScriptLogger, TraceStepScope, TraceCapturingLogger
This commit is contained in:
Joseph Doherty
@@ -0,0 +1,192 @@
|
||||
using Microsoft.Extensions.Logging;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||
|
||||
/// <summary>
|
||||
/// The row-emitting callback a <see cref="ScriptLogger"/> uses: level name, source, message,
|
||||
/// optional exception, owning step id (design 2026-09-09 D1/D2).
|
||||
/// </summary>
|
||||
/// <param name="level">Level name as it appears on the wire: <c>debug|info|warn|error</c>.</param>
|
||||
/// <param name="source">Line origin: <c>script</c> (the author's own <c>Log.*</c> call) or <c>runtime</c>.</param>
|
||||
/// <param name="message">The already-clipped message text.</param>
|
||||
/// <param name="exception">The exception attached to the line, if any.</param>
|
||||
/// <param name="stepEventId">The step row the line belongs to, or <see langword="null"/> to fall back to the run's anchor row.</param>
|
||||
public delegate void ScriptLogEmitter(string level, string source, string message, Exception? exception, Guid? stepEventId);
|
||||
|
||||
/// <summary>
|
||||
/// Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the <c>Log</c> global site scripts call.
|
||||
///
|
||||
/// <para>Every line ALWAYS forwards to the node's <see cref="ILogger"/> — an untraced run is a
|
||||
/// normal logging surface and pays nothing else. A <c>ScriptLog</c> audit row is emitted only
|
||||
/// when the run is traced, i.e. only when the owning <c>ScriptRuntimeContext</c> supplied an
|
||||
/// emitter; untraced runs construct the logger with a <see langword="null"/> emitter and the row
|
||||
/// path is a single null check.</para>
|
||||
///
|
||||
/// <para><b>Bounded (D7).</b> At most <c>maxLines</c> rows per run — one <see cref="ScriptLogger"/>
|
||||
/// instance is one run's counter, and inline shared scripts share the context, hence the counter —
|
||||
/// plus a hard <see cref="MaxMessageChars"/> cap per message. Lines past the cap are counted and
|
||||
/// dropped; <see cref="FlushDropped"/> emits the single closing warning that names the count.</para>
|
||||
///
|
||||
/// <para><b>Never throws into the script.</b> A logging or emitting failure is swallowed: this is a
|
||||
/// debug observer, and a broken observer must not fail a production script run.</para>
|
||||
/// </summary>
|
||||
public sealed class ScriptLogger
|
||||
{
|
||||
/// <summary>Per-message character cap (design D7); longer messages are truncated and suffixed with an ellipsis.</summary>
|
||||
public const int MaxMessageChars = 2_000;
|
||||
|
||||
private readonly ILogger _logger;
|
||||
private readonly ScriptLogEmitter? _emit;
|
||||
private readonly int _maxLines;
|
||||
private readonly string _instance;
|
||||
private readonly string _script;
|
||||
private readonly Guid? _executionId;
|
||||
|
||||
private int _emitted;
|
||||
private int _dropped;
|
||||
|
||||
/// <summary>Creates the <c>Log</c> global for one script run.</summary>
|
||||
/// <param name="logger">The node logger every line forwards to, traced or not.</param>
|
||||
/// <param name="emit">Row emitter; <see langword="null"/> when the run is not traced (no rows are produced).</param>
|
||||
/// <param name="maxLines">Per-run row cap (design D7); must be greater than zero.</param>
|
||||
/// <param name="instance">Instance unique name, for the structured log entry.</param>
|
||||
/// <param name="script">Script name, for the structured log entry.</param>
|
||||
/// <param name="executionId">The run's execution id, for the structured log entry.</param>
|
||||
/// <exception cref="ArgumentNullException"><paramref name="logger"/> is null.</exception>
|
||||
/// <exception cref="ArgumentOutOfRangeException"><paramref name="maxLines"/> is not greater than zero.</exception>
|
||||
public ScriptLogger(ILogger logger, ScriptLogEmitter? emit, int maxLines, string instance, string script, Guid? executionId)
|
||||
{
|
||||
ArgumentNullException.ThrowIfNull(logger);
|
||||
ArgumentOutOfRangeException.ThrowIfLessThan(maxLines, 1);
|
||||
|
||||
_logger = logger;
|
||||
_emit = emit;
|
||||
_maxLines = maxLines;
|
||||
_instance = instance;
|
||||
_script = script;
|
||||
_executionId = executionId;
|
||||
}
|
||||
|
||||
/// <summary>Logs a diagnostic line at Debug level.</summary>
|
||||
/// <param name="message">The message text (clipped at <see cref="MaxMessageChars"/>).</param>
|
||||
/// <param name="exception">An optional exception to attach to the line.</param>
|
||||
public void Debug(string message, Exception? exception = null) => Write(LogLevel.Debug, "debug", message, exception);
|
||||
|
||||
/// <summary>Logs an informational line.</summary>
|
||||
/// <param name="message">The message text (clipped at <see cref="MaxMessageChars"/>).</param>
|
||||
/// <param name="exception">An optional exception to attach to the line.</param>
|
||||
public void Info(string message, Exception? exception = null) => Write(LogLevel.Information, "info", message, exception);
|
||||
|
||||
/// <summary>Logs a warning line.</summary>
|
||||
/// <param name="message">The message text (clipped at <see cref="MaxMessageChars"/>).</param>
|
||||
/// <param name="exception">An optional exception to attach to the line.</param>
|
||||
public void Warn(string message, Exception? exception = null) => Write(LogLevel.Warning, "warn", message, exception);
|
||||
|
||||
/// <summary>Logs an error line. Does not fail the run — the script decides what to do next.</summary>
|
||||
/// <param name="message">The message text (clipped at <see cref="MaxMessageChars"/>).</param>
|
||||
/// <param name="exception">An optional exception to attach to the line.</param>
|
||||
public void Error(string message, Exception? exception = null) => Write(LogLevel.Error, "error", message, exception);
|
||||
|
||||
/// <summary>
|
||||
/// Runtime-sourced line (fed by <see cref="TraceCapturingLogger"/>); same caps, source
|
||||
/// <c>runtime</c>; does NOT forward to the <see cref="ILogger"/> — the caller already logged it,
|
||||
/// and re-logging would loop back through the decorator.
|
||||
/// </summary>
|
||||
/// <param name="level">Level name (<c>info|warn|error</c>).</param>
|
||||
/// <param name="message">The already-formatted message text.</param>
|
||||
/// <param name="exception">The exception attached to the entry, if any.</param>
|
||||
internal void Runtime(string level, string message, Exception? exception) => WriteRow(level, "runtime", message, exception);
|
||||
|
||||
/// <summary>Forwards to the node logger, then records the trace row (when traced).</summary>
|
||||
private void Write(LogLevel level, string name, string message, Exception? exception)
|
||||
{
|
||||
message = Clip(message);
|
||||
try
|
||||
{
|
||||
_logger.Log(level, exception, "[script] {Instance}/{Script} {ExecutionId}: {Message}", _instance, _script, _executionId, message);
|
||||
}
|
||||
catch
|
||||
{
|
||||
// Deliberate swallow: a failing logger sink must never propagate into the script body.
|
||||
}
|
||||
|
||||
WriteRow(name, "script", message, exception);
|
||||
}
|
||||
|
||||
/// <summary>Emits one trace row, subject to the per-run line cap.</summary>
|
||||
private void WriteRow(string level, string source, string message, Exception? exception)
|
||||
{
|
||||
if (_emit is null)
|
||||
{
|
||||
return; // Untraced run: no rows, no counting.
|
||||
}
|
||||
|
||||
if (Interlocked.Increment(ref _emitted) > _maxLines)
|
||||
{
|
||||
Interlocked.Increment(ref _dropped);
|
||||
return;
|
||||
}
|
||||
|
||||
try
|
||||
{
|
||||
_emit(level, source, Clip(message), exception, TraceStepScope.Current);
|
||||
}
|
||||
catch
|
||||
{
|
||||
// Deliberate swallow: the trace collector/audit writer is a debug observer, never a run failure.
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Run end: emits one closing warning naming the dropped count (nothing when none were
|
||||
/// dropped). Bypasses the counter on purpose — it is the one row that must always land.
|
||||
/// Idempotent: the count is cleared as it is reported, so a second call emits nothing.
|
||||
/// </summary>
|
||||
public void FlushDropped()
|
||||
{
|
||||
if (_emit is null)
|
||||
{
|
||||
return;
|
||||
}
|
||||
|
||||
var n = Interlocked.Exchange(ref _dropped, 0);
|
||||
if (n == 0)
|
||||
{
|
||||
return;
|
||||
}
|
||||
|
||||
try
|
||||
{
|
||||
_emit("warn", "runtime", $"Log truncated: {n} line(s) dropped past the per-run cap of {_maxLines}", null, null);
|
||||
}
|
||||
catch
|
||||
{
|
||||
// Deliberate swallow: same reason as WriteRow — the observer must not fail the run.
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Applies the per-message cap, marking a truncated message with a trailing ellipsis.
|
||||
///
|
||||
/// <para>Cuts one char short when the cap would land between the two halves of a surrogate
|
||||
/// pair, so an emoji straddling the boundary is dropped whole rather than leaving a lone
|
||||
/// surrogate that breaks JSON serialization downstream. Re-clipping an already-clipped message
|
||||
/// is a no-op, which matters because the script path clips once before logging and again
|
||||
/// before emitting.</para>
|
||||
/// </summary>
|
||||
private static string Clip(string? m)
|
||||
{
|
||||
if (m is null)
|
||||
{
|
||||
return string.Empty;
|
||||
}
|
||||
|
||||
if (m.Length <= MaxMessageChars)
|
||||
{
|
||||
return m;
|
||||
}
|
||||
|
||||
var keep = char.IsHighSurrogate(m[MaxMessageChars - 1]) ? MaxMessageChars - 1 : MaxMessageChars;
|
||||
return m[..keep] + "…";
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,79 @@
|
||||
using Microsoft.Extensions.Logging;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||
|
||||
/// <summary>
|
||||
/// Flow Debugger step logs (design 2026-09-09 D6): decorates the script context's
|
||||
/// <see cref="ILogger"/> while a run is traced.
|
||||
///
|
||||
/// <para>Forwards EVERYTHING to the inner logger unchanged (the node's log file is unaffected by
|
||||
/// tracing), and additionally copies <see cref="LogLevel.Information"/> and above into
|
||||
/// <c>ScriptLog</c> rows with source <c>runtime</c>, attributed to the ambient
|
||||
/// <see cref="TraceStepScope"/>. This is how the warnings the runtime logs on the script's behalf —
|
||||
/// inside <c>SetAttribute</c>, <c>WriteBatchAndWait</c>, <c>WaitInternal</c>, the sync
|
||||
/// <c>ExternalSystem.Call</c> — reach the Flow Debugger without editing each call site.</para>
|
||||
///
|
||||
/// <para>Debug and Trace are deliberately NOT captured (internal chatter, design D6), and the
|
||||
/// per-run line cap of the sink applies to what is.</para>
|
||||
///
|
||||
/// <para>Installed only when the run is traced, so an untraced run keeps the bare inner logger.</para>
|
||||
/// </summary>
|
||||
public sealed class TraceCapturingLogger : ILogger
|
||||
{
|
||||
private readonly ILogger _inner;
|
||||
private readonly ScriptLogger _sink;
|
||||
|
||||
/// <summary>Wraps <paramref name="inner"/> so that Information and above also reach <paramref name="sink"/>.</summary>
|
||||
/// <param name="inner">The node logger every entry is forwarded to.</param>
|
||||
/// <param name="sink">The run's <see cref="ScriptLogger"/>, which owns the caps and the row emitter.</param>
|
||||
/// <exception cref="ArgumentNullException"><paramref name="inner"/> or <paramref name="sink"/> is null.</exception>
|
||||
/// <exception cref="ArgumentException"><paramref name="inner"/> is itself a <see cref="TraceCapturingLogger"/>.</exception>
|
||||
public TraceCapturingLogger(ILogger inner, ScriptLogger sink)
|
||||
{
|
||||
ArgumentNullException.ThrowIfNull(inner);
|
||||
ArgumentNullException.ThrowIfNull(sink);
|
||||
if (inner is TraceCapturingLogger)
|
||||
{
|
||||
throw new ArgumentException("inner is already a TraceCapturingLogger — wrapping twice would emit two rows per script line", nameof(inner));
|
||||
}
|
||||
|
||||
_inner = inner;
|
||||
_sink = sink;
|
||||
}
|
||||
|
||||
/// <inheritdoc />
|
||||
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => _inner.BeginScope(state);
|
||||
|
||||
/// <summary>
|
||||
/// Information and above are always enabled — they are trace data even when the node's minimum
|
||||
/// level is Warning. Below Information the inner logger decides.
|
||||
/// </summary>
|
||||
/// <param name="level">The level being tested.</param>
|
||||
/// <returns><see langword="true"/> when the entry should be produced.</returns>
|
||||
public bool IsEnabled(LogLevel level) => level >= LogLevel.Information || _inner.IsEnabled(level);
|
||||
|
||||
/// <inheritdoc />
|
||||
public void Log<TState>(LogLevel level, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
|
||||
{
|
||||
// Forward first, and only if the inner logger actually wants it: IsEnabled above lies
|
||||
// upward for trace capture, so the node's own minimum level must be re-checked here.
|
||||
if (_inner.IsEnabled(level))
|
||||
{
|
||||
_inner.Log(level, eventId, state, exception, formatter);
|
||||
}
|
||||
|
||||
if (level < LogLevel.Information || level == LogLevel.None)
|
||||
{
|
||||
return;
|
||||
}
|
||||
|
||||
var name = level switch
|
||||
{
|
||||
LogLevel.Information => "info",
|
||||
LogLevel.Warning => "warn",
|
||||
_ => "error",
|
||||
};
|
||||
|
||||
_sink.Runtime(name, formatter(state, exception), exception);
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,44 @@
|
||||
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||
|
||||
/// <summary>
|
||||
/// Flow Debugger step logs (design 2026-09-09 D6): the ambient "which step is running right now"
|
||||
/// marker used to attribute runtime-sourced log lines to a step node.
|
||||
///
|
||||
/// <para>A <c>ScriptLog</c> row names its owning step explicitly (D2), but the runtime lines the
|
||||
/// node logs on the script's behalf are produced deep inside a helper — the helper knows its
|
||||
/// pre-minted step <c>EventId</c>, the logging call site does not. Rather than thread that id
|
||||
/// through every internal call, the helpers open a scope around their body and
|
||||
/// <see cref="ScriptLogger"/> reads <see cref="Current"/> when no explicit id is supplied.</para>
|
||||
///
|
||||
/// <para><see cref="AsyncLocal{T}"/> so the value flows through the helper's own awaits and
|
||||
/// nowhere else: it is captured by continuations started inside the scope and is invisible to
|
||||
/// concurrent runs on other threads of the script execution pool. Lines logged outside any scope
|
||||
/// see <see langword="null"/> and fall back to the execution's anchor row (D2).</para>
|
||||
/// </summary>
|
||||
public static class TraceStepScope
|
||||
{
|
||||
private static readonly AsyncLocal<Guid?> _current = new();
|
||||
|
||||
/// <summary>The step <c>EventId</c> owning the currently executing helper body, or <see langword="null"/> outside any scope.</summary>
|
||||
public static Guid? Current => _current.Value;
|
||||
|
||||
/// <summary>
|
||||
/// Sets the current step for the scope's lifetime; restores the previous value on dispose,
|
||||
/// so nested scopes (a helper calling another helper) unwind correctly.
|
||||
/// </summary>
|
||||
/// <param name="stepEventId">The pre-minted <c>EventId</c> of the step row this body belongs to.</param>
|
||||
/// <returns>A handle that restores the previous ambient value when disposed.</returns>
|
||||
public static IDisposable Enter(Guid stepEventId)
|
||||
{
|
||||
var prev = _current.Value;
|
||||
_current.Value = stepEventId;
|
||||
return new Restore(prev);
|
||||
}
|
||||
|
||||
/// <summary>Restores the ambient step id captured at <see cref="Enter"/> time.</summary>
|
||||
private sealed class Restore(Guid? prev) : IDisposable
|
||||
{
|
||||
/// <inheritdoc />
|
||||
public void Dispose() => _current.Value = prev;
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,320 @@
|
||||
using Microsoft.Extensions.Logging;
|
||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts;
|
||||
|
||||
/// <summary>
|
||||
/// Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the <c>Log</c> global's two obligations —
|
||||
/// ALWAYS forward to the node logger, emit a trace row ONLY when traced — plus the per-run line cap,
|
||||
/// the per-message character cap, step attribution through <see cref="TraceStepScope"/>, and the
|
||||
/// "never throws into the script" rule.
|
||||
///
|
||||
/// <para>Deliberately built without a <c>ScriptRuntimeContext</c>: the row emitter is a delegate
|
||||
/// precisely so this surface is testable on its own.</para>
|
||||
/// </summary>
|
||||
public class ScriptLoggerTests
|
||||
{
|
||||
/// <summary>One entry the logger under test forwarded to the node logger.</summary>
|
||||
private sealed record LogEntry(LogLevel Level, string Message, Exception? Exception);
|
||||
|
||||
/// <summary>A minimal recording <see cref="ILogger"/> — clearer here than a mocking framework.</summary>
|
||||
private sealed class RecordingLogger(bool enabled = true) : ILogger
|
||||
{
|
||||
public List<LogEntry> Entries { get; } = [];
|
||||
|
||||
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
|
||||
|
||||
public bool IsEnabled(LogLevel logLevel) => enabled;
|
||||
|
||||
public void Log<TState>(LogLevel level, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter) =>
|
||||
Entries.Add(new LogEntry(level, formatter(state, exception), exception));
|
||||
}
|
||||
|
||||
/// <summary>One row the logger under test handed to its emitter.</summary>
|
||||
private sealed record Row(string Level, string Source, string Message, Exception? Exception, Guid? StepEventId);
|
||||
|
||||
private static (ScriptLogger Logger, RecordingLogger Node, List<Row> Rows) MakeTraced(int maxLines = 200)
|
||||
{
|
||||
var node = new RecordingLogger();
|
||||
var rows = new List<Row>();
|
||||
var logger = new ScriptLogger(
|
||||
node,
|
||||
(level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)),
|
||||
maxLines,
|
||||
instance: "CvdReactor01",
|
||||
script: "OnHeartbeat",
|
||||
executionId: Guid.NewGuid());
|
||||
return (logger, node, rows);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void UntracedRun_ForwardsToTheNodeLogger_AndEmitsNoRow()
|
||||
{
|
||||
// D5: an untraced run is an ordinary logging surface — the author's messages are never lost,
|
||||
// but nothing is audited.
|
||||
var node = new RecordingLogger();
|
||||
var logger = new ScriptLogger(node, emit: null, maxLines: 200, "CvdReactor01", "OnHeartbeat", Guid.NewGuid());
|
||||
|
||||
logger.Info("hello");
|
||||
logger.Warn("careful");
|
||||
|
||||
Assert.Equal(2, node.Entries.Count);
|
||||
Assert.Equal(LogLevel.Information, node.Entries[0].Level);
|
||||
Assert.Contains("hello", node.Entries[0].Message);
|
||||
Assert.Equal(LogLevel.Warning, node.Entries[1].Level);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void TracedRun_EmitsOneScriptSourcedRowPerLine()
|
||||
{
|
||||
var (logger, node, rows) = MakeTraced();
|
||||
|
||||
logger.Info("msg");
|
||||
|
||||
Assert.Single(node.Entries);
|
||||
var row = Assert.Single(rows);
|
||||
Assert.Equal(("info", "script", "msg", (Exception?)null, (Guid?)null), (row.Level, row.Source, row.Message, row.Exception, row.StepEventId));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void EveryLevel_MapsToItsWireName()
|
||||
{
|
||||
var (logger, node, rows) = MakeTraced();
|
||||
|
||||
logger.Debug("d");
|
||||
logger.Info("i");
|
||||
logger.Warn("w");
|
||||
logger.Error("e");
|
||||
|
||||
Assert.Equal(["debug", "info", "warn", "error"], rows.Select(r => r.Level));
|
||||
Assert.Equal(
|
||||
[LogLevel.Debug, LogLevel.Information, LogLevel.Warning, LogLevel.Error],
|
||||
node.Entries.Select(e => e.Level));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void LineInsideAStepScope_IsAttributedToThatStep_AndTheScopeUnwinds()
|
||||
{
|
||||
// D6: the ambient scope is how a line written inside a helper body names its step node.
|
||||
var (logger, _, rows) = MakeTraced();
|
||||
var stepId = Guid.NewGuid();
|
||||
|
||||
using (TraceStepScope.Enter(stepId))
|
||||
{
|
||||
Assert.Equal(stepId, TraceStepScope.Current);
|
||||
logger.Info("inside");
|
||||
}
|
||||
|
||||
Assert.Null(TraceStepScope.Current);
|
||||
logger.Info("outside");
|
||||
|
||||
Assert.Equal(stepId, rows[0].StepEventId);
|
||||
Assert.Null(rows[1].StepEventId);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void NestedStepScopes_Unwind_ToTheEnclosingStep()
|
||||
{
|
||||
// A helper calling another helper: the inner step owns its own lines, and the outer step
|
||||
// gets its attribution back the moment the inner scope closes.
|
||||
var (logger, _, rows) = MakeTraced();
|
||||
var outer = Guid.NewGuid();
|
||||
var inner = Guid.NewGuid();
|
||||
|
||||
using (TraceStepScope.Enter(outer))
|
||||
{
|
||||
using (TraceStepScope.Enter(inner))
|
||||
{
|
||||
Assert.Equal(inner, TraceStepScope.Current);
|
||||
logger.Info("inner");
|
||||
}
|
||||
|
||||
Assert.Equal(outer, TraceStepScope.Current);
|
||||
logger.Info("outer");
|
||||
}
|
||||
|
||||
Assert.Null(TraceStepScope.Current);
|
||||
Assert.Equal(inner, rows[0].StepEventId);
|
||||
Assert.Equal(outer, rows[1].StepEventId);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PastThePerRunCap_LinesAreDropped_AndFlushDroppedNamesTheCount_Once()
|
||||
{
|
||||
// D7: bounded per run; the closing row bypasses the cap because it is the only signal that
|
||||
// anything was lost — and it is idempotent so a double flush cannot duplicate it.
|
||||
var (logger, _, rows) = MakeTraced(maxLines: 3);
|
||||
|
||||
for (var i = 0; i < 5; i++)
|
||||
{
|
||||
logger.Info($"line {i}");
|
||||
}
|
||||
|
||||
Assert.Equal(3, rows.Count);
|
||||
Assert.Equal(["line 0", "line 1", "line 2"], rows.Select(r => r.Message));
|
||||
|
||||
logger.FlushDropped();
|
||||
|
||||
Assert.Equal(4, rows.Count);
|
||||
var closing = rows[^1];
|
||||
Assert.Equal("warn", closing.Level);
|
||||
Assert.Equal("runtime", closing.Source);
|
||||
Assert.Contains("2 line(s)", closing.Message);
|
||||
Assert.Null(closing.StepEventId);
|
||||
|
||||
logger.FlushDropped();
|
||||
|
||||
Assert.Equal(4, rows.Count);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FlushDropped_EmitsNothing_WhenNoLineWasDropped()
|
||||
{
|
||||
var (logger, _, rows) = MakeTraced(maxLines: 3);
|
||||
|
||||
logger.Info("only one");
|
||||
logger.FlushDropped();
|
||||
|
||||
Assert.Single(rows);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void MessagesLongerThanTheCap_AreClippedWithAnEllipsis()
|
||||
{
|
||||
var (logger, _, rows) = MakeTraced();
|
||||
|
||||
logger.Info(new string('x', 2_500));
|
||||
|
||||
var message = Assert.Single(rows).Message;
|
||||
Assert.Equal(ScriptLogger.MaxMessageChars + 1, message.Length);
|
||||
Assert.EndsWith("…", message);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void AMessageExactlyAtTheCap_PassesThroughUnclipped()
|
||||
{
|
||||
var (logger, _, rows) = MakeTraced();
|
||||
var exact = new string('x', ScriptLogger.MaxMessageChars);
|
||||
|
||||
logger.Info(exact);
|
||||
|
||||
Assert.Equal(exact, Assert.Single(rows).Message);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ASurrogatePairStraddlingTheCap_IsDroppedWhole()
|
||||
{
|
||||
// Cutting between the halves would leave a lone surrogate, which breaks JSON serialization
|
||||
// of the audit row further down the pipe.
|
||||
var (logger, _, rows) = MakeTraced();
|
||||
var straddling = new string('x', ScriptLogger.MaxMessageChars - 1) + "🚀" + new string('y', 10);
|
||||
|
||||
logger.Info(straddling);
|
||||
|
||||
var message = Assert.Single(rows).Message;
|
||||
Assert.Equal(ScriptLogger.MaxMessageChars, message.Length);
|
||||
Assert.EndsWith("…", message);
|
||||
Assert.DoesNotContain(message, static c => char.IsSurrogate(c));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void AThrowingEmitter_NeverReachesTheScript_AndTheNodeLoggerStillGotTheLine()
|
||||
{
|
||||
// The whole feature is a debug observer: a broken observer must not fail a production run.
|
||||
var node = new RecordingLogger();
|
||||
var logger = new ScriptLogger(
|
||||
node,
|
||||
(_, _, _, _, _) => throw new InvalidOperationException("collector is broken"),
|
||||
maxLines: 200,
|
||||
"CvdReactor01",
|
||||
"OnHeartbeat",
|
||||
Guid.NewGuid());
|
||||
|
||||
logger.Info("still logged");
|
||||
|
||||
Assert.Single(node.Entries);
|
||||
Assert.Contains("still logged", node.Entries[0].Message);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void AThrowingNodeLogger_NeverReachesTheScript_AndTheRowIsStillEmitted()
|
||||
{
|
||||
var rows = new List<Row>();
|
||||
var logger = new ScriptLogger(
|
||||
new ThrowingLogger(),
|
||||
(level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)),
|
||||
maxLines: 200,
|
||||
"CvdReactor01",
|
||||
"OnHeartbeat",
|
||||
Guid.NewGuid());
|
||||
|
||||
logger.Warn("sink is down");
|
||||
|
||||
Assert.Single(rows);
|
||||
}
|
||||
|
||||
/// <summary>A node logger whose sink fails, standing in for a wedged Serilog sink.</summary>
|
||||
private sealed class ThrowingLogger : ILogger
|
||||
{
|
||||
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
|
||||
|
||||
public bool IsEnabled(LogLevel logLevel) => true;
|
||||
|
||||
public void Log<TState>(LogLevel level, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter) =>
|
||||
throw new InvalidOperationException("sink is down");
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void AnAttachedException_ReachesBothTheNodeLoggerAndTheRow()
|
||||
{
|
||||
var (logger, node, rows) = MakeTraced();
|
||||
var boom = new InvalidOperationException("boom");
|
||||
|
||||
logger.Error("x", boom);
|
||||
|
||||
Assert.Same(boom, node.Entries[0].Exception);
|
||||
Assert.Same(boom, Assert.Single(rows).Exception);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RuntimeLines_AreRowOnly_AndCarryTheRuntimeSource()
|
||||
{
|
||||
// The capturing logger has already written the entry to the node logger; re-logging it here
|
||||
// would double it (and loop straight back through the decorator).
|
||||
var (logger, node, rows) = MakeTraced();
|
||||
|
||||
logger.Runtime("warn", "tag write timed out", null);
|
||||
|
||||
Assert.Empty(node.Entries);
|
||||
var row = Assert.Single(rows);
|
||||
Assert.Equal("warn", row.Level);
|
||||
Assert.Equal("runtime", row.Source);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RuntimeLines_ShareThePerRunCapWithScriptLines()
|
||||
{
|
||||
var (logger, _, rows) = MakeTraced(maxLines: 2);
|
||||
|
||||
logger.Info("script line");
|
||||
logger.Runtime("info", "runtime line", null);
|
||||
logger.Runtime("info", "dropped", null);
|
||||
|
||||
Assert.Equal(2, rows.Count);
|
||||
logger.FlushDropped();
|
||||
Assert.Contains("1 line(s)", rows[^1].Message);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void MaxLinesMustBePositive()
|
||||
{
|
||||
Assert.Throws<ArgumentOutOfRangeException>(() =>
|
||||
new ScriptLogger(new RecordingLogger(), emit: null, maxLines: 0, "i", "s", null));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void TheNodeLoggerIsRequired()
|
||||
{
|
||||
Assert.Throws<ArgumentNullException>(() => new ScriptLogger(null!, emit: null, maxLines: 1, "i", "s", null));
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,168 @@
|
||||
using Microsoft.Extensions.Logging;
|
||||
using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts;
|
||||
|
||||
namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts;
|
||||
|
||||
/// <summary>
|
||||
/// Flow Debugger step logs (design 2026-09-09 D6): the decorator installed over the script
|
||||
/// context's logger while a run is traced. It must forward everything the node would have logged
|
||||
/// anyway, capture Information and above as <c>runtime</c> rows — including levels the node's own
|
||||
/// minimum level suppresses, because they are trace data, not node log output — and never capture
|
||||
/// Debug/Trace chatter.
|
||||
/// </summary>
|
||||
public class TraceCapturingLoggerTests
|
||||
{
|
||||
/// <summary>One row the sink's emitter received.</summary>
|
||||
private sealed record Row(string Level, string Source, string Message, Exception? Exception, Guid? StepEventId);
|
||||
|
||||
/// <summary>An inner logger that records what it was asked to write, at a configurable minimum level.</summary>
|
||||
private sealed class RecordingLogger(LogLevel minimum = LogLevel.Trace) : ILogger
|
||||
{
|
||||
public List<(LogLevel Level, string Message)> Entries { get; } = [];
|
||||
public List<object?> Scopes { get; } = [];
|
||||
|
||||
public IDisposable? BeginScope<TState>(TState state) where TState : notnull
|
||||
{
|
||||
Scopes.Add(state);
|
||||
return null;
|
||||
}
|
||||
|
||||
public bool IsEnabled(LogLevel logLevel) => logLevel >= minimum;
|
||||
|
||||
public void Log<TState>(LogLevel level, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter) =>
|
||||
Entries.Add((level, formatter(state, exception)));
|
||||
}
|
||||
|
||||
private static (TraceCapturingLogger Logger, RecordingLogger Inner, List<Row> Rows) Make(LogLevel innerMinimum = LogLevel.Trace)
|
||||
{
|
||||
var inner = new RecordingLogger(innerMinimum);
|
||||
var rows = new List<Row>();
|
||||
var sink = new ScriptLogger(
|
||||
new RecordingLogger(),
|
||||
(level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)),
|
||||
maxLines: 200,
|
||||
instance: "CvdReactor01",
|
||||
script: "OnHeartbeat",
|
||||
executionId: Guid.NewGuid());
|
||||
return (new TraceCapturingLogger(inner, sink), inner, rows);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Debug_IsForwarded_ButNotCaptured()
|
||||
{
|
||||
var (logger, inner, rows) = Make();
|
||||
|
||||
logger.LogDebug("internal chatter");
|
||||
|
||||
Assert.Single(inner.Entries);
|
||||
Assert.Empty(rows);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Warning_IsCapturedAsARuntimeRow_WithItsException()
|
||||
{
|
||||
var (logger, inner, rows) = Make();
|
||||
var boom = new TimeoutException("no reply");
|
||||
|
||||
logger.LogWarning(boom, "tag write timed out after {Ms} ms", 5_000);
|
||||
|
||||
Assert.Single(inner.Entries);
|
||||
var row = Assert.Single(rows);
|
||||
Assert.Equal("warn", row.Level);
|
||||
Assert.Equal("runtime", row.Source);
|
||||
Assert.Equal("tag write timed out after 5000 ms", row.Message);
|
||||
Assert.Same(boom, row.Exception);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ErrorAndCritical_AreBothCapturedAsError()
|
||||
{
|
||||
var (logger, _, rows) = Make();
|
||||
|
||||
logger.LogError("bad");
|
||||
logger.LogCritical("worse");
|
||||
|
||||
Assert.Equal(["error", "error"], rows.Select(r => r.Level));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void InformationIsEnabled_EvenWhenTheInnerLoggerSaysNo()
|
||||
{
|
||||
// A node whose Serilog minimum is Warning must still contribute Information lines to a trace.
|
||||
var (logger, inner, rows) = Make(innerMinimum: LogLevel.Warning);
|
||||
|
||||
Assert.False(inner.IsEnabled(LogLevel.Information));
|
||||
Assert.True(logger.IsEnabled(LogLevel.Information));
|
||||
|
||||
logger.LogInformation("captured anyway");
|
||||
|
||||
Assert.Empty(inner.Entries);
|
||||
var row = Assert.Single(rows);
|
||||
Assert.Equal("info", row.Level);
|
||||
Assert.Equal("captured anyway", row.Message);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void BelowInformation_TheInnerLoggerDecidesEnablement()
|
||||
{
|
||||
var (logger, _, _) = Make(innerMinimum: LogLevel.Warning);
|
||||
|
||||
Assert.False(logger.IsEnabled(LogLevel.Debug));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ADisabledInnerLogger_IsNotWrittenTo_ButTheRowIsStillCaptured()
|
||||
{
|
||||
var (logger, inner, rows) = Make(innerMinimum: LogLevel.Critical);
|
||||
|
||||
logger.LogWarning("suppressed on the node");
|
||||
|
||||
Assert.Empty(inner.Entries);
|
||||
Assert.Single(rows);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void CapturedLines_CarryTheAmbientStepId()
|
||||
{
|
||||
var (logger, _, rows) = Make();
|
||||
var stepId = Guid.NewGuid();
|
||||
|
||||
using (TraceStepScope.Enter(stepId))
|
||||
{
|
||||
logger.LogInformation("inside the helper");
|
||||
}
|
||||
|
||||
Assert.Equal(stepId, Assert.Single(rows).StepEventId);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Ctor_RejectsAnAlreadyDecoratedLogger()
|
||||
{
|
||||
// Wrapping twice would forward each script line through two capture stages and emit two
|
||||
// runtime rows per line — and would burn the run's line cap at double rate.
|
||||
var (already, _, _) = Make();
|
||||
var sink = new ScriptLogger(new RecordingLogger(), emit: null, maxLines: 200, "i", "s", null);
|
||||
|
||||
var ex = Assert.Throws<ArgumentException>(() => new TraceCapturingLogger(already, sink));
|
||||
Assert.Equal("inner", ex.ParamName);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Ctor_RequiresBothCollaborators()
|
||||
{
|
||||
var sink = new ScriptLogger(new RecordingLogger(), emit: null, maxLines: 200, "i", "s", null);
|
||||
|
||||
Assert.Throws<ArgumentNullException>(() => new TraceCapturingLogger(null!, sink));
|
||||
Assert.Throws<ArgumentNullException>(() => new TraceCapturingLogger(new RecordingLogger(), null!));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void BeginScope_DelegatesToTheInnerLogger()
|
||||
{
|
||||
var (logger, inner, _) = Make();
|
||||
|
||||
logger.BeginScope("state");
|
||||
|
||||
Assert.Equal(["state"], inner.Scopes);
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user