diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs
index d9a7e73d..fdc13e20 100644
--- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs
+++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptCompilationService.cs
@@ -344,6 +344,9 @@ public class ScriptGlobals
///
public AlarmsAccessor Alarms => Instance.Alarms;
+ /// Leveled per-run logging (design 2026-09-09). Usage: Log.Info("…"), Log.Warn("…", ex). Always reaches the node log; becomes Flow Debugger trace rows only for a traced run.
+ public ScriptLogger Log => Instance.Log;
+
///
/// Parent composition (null when this script is on a root-level template).
/// Parent.Attributes["SpeedRPM"] reaches the parent's attribute;
diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs
index ea9f4a8b..c15a724c 100644
--- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs
+++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs
@@ -45,7 +45,24 @@ public class ScriptRuntimeContext
private readonly int _currentCallDepth;
private readonly int _maxCallDepth;
private readonly TimeSpan _askTimeout;
- private readonly ILogger _logger;
+
+ ///
+ /// The logger every runtime diagnostic in this context goes through. NOT readonly because a
+ /// TRACED run swaps in a in the constructor (step-logs
+ /// design 2026-09-09 D6), so the warnings the runtime logs on the script's behalf become
+ /// ScriptLog rows attributed to the step that was running. An untraced run keeps the
+ /// injected logger untouched — no decorator, no allocation.
+ ///
+ private ILogger _logger;
+
+ ///
+ /// The UNDECORATED injected logger. Every diagnostic emitted from inside the log path itself
+ /// () must use this one: routing it through would be
+ /// captured by the decorator and re-enter in a loop. Also the logger a
+ /// child (inline shared-script) context is built with, since
+ /// refuses to wrap itself.
+ ///
+ private readonly ILogger _innerLogger;
private readonly string _instanceName;
///
@@ -189,6 +206,48 @@ public class ScriptRuntimeContext
///
private readonly Action? _traceSink;
+ ///
+ /// Step logs (design 2026-09-09 D7): the per-run ScriptLog row cap this context's
+ /// enforces, carried over verbatim into an inline shared-script child.
+ ///
+ private readonly int _maxLogLinesPerRun;
+
+ ///
+ /// Step logs (design D4): the bare script name a ScriptLog row targets — the SAME value
+ /// the run's ScriptRun anchor row uses, so the Flow Debugger's anchor fallback lines up.
+ /// Derived from _sourceScript by dropping its ScriptActor: / AlarmActor:
+ /// prefix; the instance name when no script owns the context.
+ ///
+ private readonly string _logTarget;
+
+ ///
+ /// Step logs (design D4): per-run emission counter stamped on every ScriptLog row as
+ /// ScriptTraceExtra.Seq, so lines produced inside the same millisecond still sort.
+ ///
+ private int _logSeq;
+
+ ///
+ /// Step logs (design 2026-09-09 D4/D5): the Log global site scripts call —
+ /// Log.Debug/Info/Warn/Error(message, exception?).
+ ///
+ /// Every line ALWAYS reaches the node's , traced or not. A
+ /// ScriptLog trace row is additionally produced only when this run is traced: an
+ /// untraced context builds the logger with a null emitter, so the row path is one null check
+ /// and the untraced run is byte-identical to the pre-feature behaviour.
+ ///
+ /// Bounded per run (D7) and never throws into the script — see
+ /// .
+ ///
+ /// An inline shared script SHARES its caller's logger (design §5): a context built
+ /// by is handed this same instance rather than
+ /// making its own, so the caller and every shared script it calls share ONE per-run line cap and
+ /// ONE closing "dropped lines" row. The consequence to know: a shared script's lines carry the
+ /// PARENT run's ExecutionId and therefore land on the parent's ScriptRun node in
+ /// the Flow Debugger — not on the shared script's own execution node, even though its
+ /// ApiCall/DbWrite/step rows still chain under their own execution.
+ ///
+ public ScriptLogger Log { get; }
+
///
/// Initializes a new script runtime context with all dependencies for script
/// execution, external system calls, database access, and notification delivery.
@@ -240,6 +299,17 @@ public class ScriptRuntimeContext
///
/// Flow Debugger trace flag — see design 2026-09-05 §5.2. Defaults to untraced.
/// Flow Debugger per-run inline trace sink (design §5.4); null when untraced.
+ ///
+ /// Step logs (design 2026-09-09 D7): the per-run ScriptLog row cap for
+ /// — mirrors SiteRuntimeOptions.MaxLogLinesPerRun, which the script run launcher passes
+ /// in. Values below 1 are clamped to 1: a mis-set option must not make every script run throw.
+ ///
+ ///
+ /// Step logs (design §5): an existing to adopt as
+ /// instead of creating one — supplied only by
+ /// , so an inline shared script shares its
+ /// caller's line cap and anchor. Null (the default) creates this run's own logger.
+ ///
public ScriptRuntimeContext(
IActorRef instanceActor,
SharedScriptLibrary sharedScriptLibrary,
@@ -263,7 +333,9 @@ public class ScriptRuntimeContext
ISiteEventLogger? siteEventLogger = null,
CancellationToken scriptTimeoutToken = default,
bool isTraced = false,
- FlowTraceCollector? traceCollector = null)
+ FlowTraceCollector? traceCollector = null,
+ int maxLogLinesPerRun = 200,
+ ScriptLogger? sharedLog = null)
{
_instanceActor = instanceActor;
_sharedScriptLibrary = sharedScriptLibrary;
@@ -271,6 +343,7 @@ public class ScriptRuntimeContext
_maxCallDepth = maxCallDepth;
_askTimeout = askTimeout;
_instanceName = instanceName;
+ _innerLogger = logger;
_logger = logger;
_externalSystemClient = externalSystemClient;
_databaseGateway = databaseGateway;
@@ -298,6 +371,28 @@ public class ScriptRuntimeContext
_isTraced = isTraced;
_traceCollector = traceCollector;
_traceSink = traceCollector is null ? null : Collect;
+
+ // Step logs (design 2026-09-09 D4-D6). ORDER MATTERS: the Log global is built over the
+ // UNDECORATED logger first, and only then — when traced — does the context's own logger
+ // become the capturing decorator over that same sink. Building them the other way round
+ // would hand ScriptLogger the decorator (every Log.* line logged, captured and re-emitted
+ // as a second row) and TraceCapturingLogger refuses to wrap itself for exactly that reason.
+ _maxLogLinesPerRun = Math.Max(1, maxLogLinesPerRun);
+ _logTarget = string.IsNullOrEmpty(_sourceScript)
+ // No single script owns the context — the instance is the closest honest target.
+ ? _instanceName
+ // "ScriptActor:Foo" / "AlarmActor:Foo" -> "Foo"; a bare name is unchanged (IndexOf -1).
+ : _sourceScript[(_sourceScript.IndexOf(':') + 1)..];
+ // An inline shared script adopts its caller's logger (design §5) — one counter, one anchor,
+ // one closing row for the whole inline chain. Everyone else builds their own.
+ Log = sharedLog ?? new ScriptLogger(
+ logger, isTraced ? EmitLog : null, _maxLogLinesPerRun, _instanceName, _logTarget, _executionId);
+ if (isTraced)
+ {
+ // The child's OWN undecorated logger, decorated over the SHARED sink: the capturing
+ // decorator is per-context (it must not be handed on), the sink behind it is not.
+ _logger = new TraceCapturingLogger(logger, Log);
+ }
}
///
@@ -378,7 +473,9 @@ public class ScriptRuntimeContext
_maxCallDepth,
_askTimeout,
_instanceName,
- _logger,
+ // Step logs (D6): the UNDECORATED logger — the child installs its own capturing
+ // decorator when traced, and TraceCapturingLogger refuses to wrap another one.
+ _innerLogger,
_externalSystemClient,
_databaseGateway,
_storeAndForward,
@@ -401,7 +498,12 @@ public class ScriptRuntimeContext
// Flow Debugger (design §5.2): a traced root traces its whole tree — the inline
// shared script shares the same flag AND the same inline sink.
isTraced: _isTraced,
- traceCollector: _traceCollector);
+ traceCollector: _traceCollector,
+ maxLogLinesPerRun: _maxLogLinesPerRun,
+ // Step logs (design §5): the inline shared script is its own execution node for step
+ // rows, but it SHARES this run's Log — one line cap and one anchor for the whole
+ // inline chain, so its lines carry this run's ExecutionId.
+ sharedLog: Log);
}
///
@@ -411,9 +513,22 @@ public class ScriptRuntimeContext
/// throws into the script, and hands raw payloads to the writer whose redactor applies
/// the configured size cap (§9) exactly as the other channels do.
///
+ /// The trace row's kind.
+ /// The row's lifecycle status.
+ /// The row's target (attribute name, script name, …).
+ /// When the traced action started — the row's OccurredAtUtc.
+ /// How long the action took.
+ /// Request summary.
+ /// Response summary.
+ /// Error message on a failed row.
+ /// Kind-specific extra detail.
+ ///
+ /// Step logs (design 2026-09-09 D6): the step's PRE-MINTED EventId, so the log lines the
+ /// runtime produced inside the step's can name it. Null mints one.
+ ///
private void EmitTrace(
AuditKind kind, AuditStatus status, string target, DateTime startedUtc, int durationMs,
- string? input, string? output, string? error, ScriptTraceExtra? extra)
+ string? input, string? output, string? error, ScriptTraceExtra? extra, Guid? eventId = null)
{
if (!_isTraced) return;
AuditEvent evt;
@@ -421,6 +536,7 @@ public class ScriptRuntimeContext
{
evt = ScadaBridgeAuditEventFactory.Create(
AuditChannel.ScriptTrace, kind, status,
+ eventId: eventId,
occurredAtUtc: DateTime.SpecifyKind(startedUtc, DateTimeKind.Utc),
actor: _sourceScript, target: target, sourceNode: _sourceNode,
executionId: _executionId, parentExecutionId: _parentExecutionId,
@@ -456,6 +572,79 @@ public class ScriptRuntimeContext
}
}
+ ///
+ /// Step logs (design 2026-09-09 D4/D7): emits one ScriptTrace/ScriptLog row for a
+ /// single log line — the collector's LOW-PRIORITY lane first (log lines must never crowd out
+ /// the step rows a run emits at its end), then the best-effort .
+ ///
+ /// This is the emitter handed to , and it is wired only when the run is
+ /// traced. Every diagnostic it logs itself goes to , NEVER to
+ /// : on a traced run the latter is the capturing decorator, which would
+ /// feed the warning straight back into this method.
+ ///
+ /// Level name as it appears on the wire: debug|info|warn|error.
+ /// Line origin: script (a Log.* call) or runtime.
+ /// The already-clipped message text.
+ /// The exception attached to the line, if any.
+ /// The owning step's EventId; null falls back to the run's anchor row (D2).
+ private void EmitLog(string level, string source, string message, Exception? exception, Guid? stepEventId)
+ {
+ if (!_isTraced) return;
+ AuditEvent evt;
+ try
+ {
+ evt = ScadaBridgeAuditEventFactory.Create(
+ AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered,
+ occurredAtUtc: DateTime.UtcNow,
+ actor: _sourceScript, target: _logTarget, sourceNode: _sourceNode,
+ executionId: _executionId, parentExecutionId: _parentExecutionId,
+ sourceSiteId: string.IsNullOrEmpty(_siteId) ? null : _siteId,
+ sourceInstanceId: _instanceName, sourceScript: _sourceScript,
+ errorMessage: exception?.Message, errorDetail: exception?.ToString(),
+ requestSummary: message,
+ extra: new ScriptTraceExtra
+ {
+ LogLevel = level,
+ LogSource = source,
+ StepEventId = stepEventId,
+ Seq = Interlocked.Increment(ref _logSeq),
+ }.ToJson());
+ }
+ catch (Exception ex)
+ {
+ _innerLogger.LogWarning(ex, "Flow trace log-line build failed at {Level}", level);
+ return;
+ }
+
+ try
+ {
+ // Low-priority lane (D7): dropped lines set LogsTruncated, not Truncated.
+ _traceCollector?.Add(evt, lowPriority: true);
+ }
+ catch (Exception ex)
+ {
+ _innerLogger.LogWarning(ex, "Flow trace collector rejected log line ({EventId})", evt.EventId);
+ }
+
+ if (_auditWriter is null) return;
+ try
+ {
+ var t = _auditWriter.WriteAsync(evt, CancellationToken.None);
+ if (!t.IsCompletedSuccessfully)
+ {
+ _ = t.ContinueWith(
+ x => _innerLogger.LogWarning(x.Exception, "Flow trace log-line write failed ({EventId})", evt.EventId),
+ CancellationToken.None,
+ TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously,
+ TaskScheduler.Default);
+ }
+ }
+ catch (Exception ex)
+ {
+ _innerLogger.LogWarning(ex, "Flow trace log-line write failed ({EventId})", evt.EventId);
+ }
+ }
+
/// Serialises a small trace payload; null on failure (best-effort, like the audit helpers).
private static string? TraceJson(object? value)
{
@@ -618,6 +807,11 @@ public class ScriptRuntimeContext
var startedUtc = DateTime.UtcNow;
var sw = _isTraced ? Stopwatch.StartNew() : null;
+ // Step logs (design D6): pre-mint this step's row id and make it the ambient step for the
+ // body, so a warning the runtime logs while the wait is in flight names THIS row. Nothing
+ // is minted and no scope is opened on an untraced run.
+ Guid? stepId = _isTraced ? Guid.NewGuid() : null;
+ using var step = stepId is { } waitStepId ? TraceStepScope.Enter(waitStepId) : null;
WaitForAttributeResponse response;
try
{
@@ -648,7 +842,8 @@ public class ScriptRuntimeContext
{
WaitAttribute = name, WaitTarget = targetValueEncoded ?? (predicate is null ? null : ""),
WaitTimeoutMs = (int)timeout.TotalMilliseconds, WaitOutcome = "cancelled",
- });
+ },
+ eventId: stepId);
}
throw;
}
@@ -670,7 +865,8 @@ public class ScriptRuntimeContext
WaitTimeoutMs = (int)timeout.TotalMilliseconds,
WaitOutcome = outcome,
ObservedValue = observed,
- });
+ },
+ eventId: stepId);
}
return response;
@@ -706,6 +902,10 @@ public class ScriptRuntimeContext
var startedUtc = DateTime.UtcNow;
var sw = _isTraced ? Stopwatch.StartNew() : null;
+ // Step logs (design D6): one pre-minted row id shared by BOTH emit points below, opened as
+ // the ambient step so runtime warnings logged during the write are attributed to it.
+ Guid? stepId = _isTraced ? Guid.NewGuid() : null;
+ using var step = stepId is { } writeStepId ? TraceStepScope.Enter(writeStepId) : null;
SetStaticAttributeResponse response;
try
{
@@ -717,7 +917,8 @@ public class ScriptRuntimeContext
{
EmitTrace(AuditKind.AttributeWrite, AuditStatus.Failed, attributeName, startedUtc,
(int)sw.ElapsedMilliseconds, TraceJson(new { attribute = attributeName, value }), null, ex.Message,
- new ScriptTraceExtra { Writes = [new AttributeWriteDetail(attributeName, value, false, ex.Message)] });
+ new ScriptTraceExtra { Writes = [new AttributeWriteDetail(attributeName, value, false, ex.Message)] },
+ eventId: stepId);
throw;
}
@@ -732,7 +933,8 @@ public class ScriptRuntimeContext
extra: new ScriptTraceExtra
{
Writes = [new AttributeWriteDetail(attributeName, value, response.Success, response.ErrorMessage)],
- });
+ },
+ eventId: stepId);
}
if (!response.Success)
@@ -772,6 +974,10 @@ public class ScriptRuntimeContext
// than an AskTimeoutException here. Honors the script execution-timeout token.
var startedUtc = DateTime.UtcNow;
var sw = _isTraced ? Stopwatch.StartNew() : null;
+ // Step logs (design D6): the batch's own step. The trailing WaitAttribute opens its own
+ // nested scope and restores this one on the way out, so each leg owns its lines.
+ Guid? stepId = _isTraced ? Guid.NewGuid() : null;
+ using var step = stepId is { } batchStepId ? TraceStepScope.Enter(batchStepId) : null;
var batchResp = await _instanceActor.Ask(
batchReq, TimeSpan.FromSeconds(35), _scriptTimeoutToken);
@@ -789,7 +995,8 @@ public class ScriptRuntimeContext
input: TraceJson(new { values = encodedValues, trigger = triggerAttr, triggerValue = triggerEncoded }),
output: null,
error: batchResp.ErrorMessage,
- extra: new ScriptTraceExtra { TriggerAttribute = triggerAttr, TriggerValue = triggerEncoded, Writes = writes });
+ extra: new ScriptTraceExtra { TriggerAttribute = triggerAttr, TriggerValue = triggerEncoded, Writes = writes },
+ eventId: stepId);
}
if (!batchResp.Success)
@@ -873,7 +1080,9 @@ public class ScriptRuntimeContext
// it onto SiteCallOperational.SourceNode.
_sourceNode,
// Flow Debugger: the outbound rows ride the inline collector (null when untraced).
- traceSink: _traceSink);
+ traceSink: _traceSink,
+ // Step logs (D6): the run's trace flag — the authority for the sync Call's step scope.
+ isTraced: _isTraced);
///
/// Provides access to database operations.
@@ -1131,6 +1340,15 @@ public class ScriptRuntimeContext
///
private readonly Action? _traceSink;
+ ///
+ /// Step logs (design 2026-09-09 D6): whether the owning run is traced. The authority for
+ /// opening a around . Deliberately NOT
+ /// : the sink is null whenever the run has no inline collector,
+ /// which is a different question from "is this run traced" — a traced run without a
+ /// collector still writes durable ScriptLog rows that must name their step.
+ ///
+ private readonly bool _isTraced;
+
///
/// Initializes a new external system helper for script API calls.
///
@@ -1145,6 +1363,7 @@ public class ScriptRuntimeContext
/// Optional identifier of the parent execution (for routed calls).
/// Optional cluster node identifier (node-a/node-b) for audit stamping.
/// Flow Debugger inline collector — receives the same each emit hands to the writer/forwarder; null when untraced.
+ /// Step logs (design D6): true when the owning run is traced, so pre-mints its row id and publishes it as the ambient step. Defaults to false for direct (test) construction.
// Internal constructor for tests living in ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests
// (via InternalsVisibleTo). Production sites resolve the helper through
// ScriptRuntimeContext.ExternalSystem.
@@ -1168,7 +1387,8 @@ public class ScriptRuntimeContext
ICachedCallTelemetryForwarder? cachedForwarder = null,
Guid? parentExecutionId = null,
string? sourceNode = null,
- Action? traceSink = null)
+ Action? traceSink = null,
+ bool isTraced = false)
{
_client = client;
_instanceName = instanceName;
@@ -1181,6 +1401,7 @@ public class ScriptRuntimeContext
_parentExecutionId = parentExecutionId;
_sourceNode = sourceNode;
_traceSink = GuardTraceSink(traceSink, logger);
+ _isTraced = isTraced;
}
///
@@ -1207,6 +1428,13 @@ public class ScriptRuntimeContext
// audit emission is best-effort.
var occurredAtUtc = DateTime.UtcNow;
var startTicks = Stopwatch.GetTimestamp();
+ // Step logs (design D6): pre-mint this call's audit row id and make it the ambient step
+ // so the helper's own warnings — and anything the client logs through this context —
+ // are attributed to the API-call node. Gated on the run's trace flag, NOT on the
+ // presence of an inline collector: a traced run without one still writes durable
+ // ScriptLog rows that need the step id. Untraced mints nothing and opens no scope.
+ Guid? stepId = _isTraced ? Guid.NewGuid() : null;
+ using var step = stepId is { } callStepId ? TraceStepScope.Enter(callStepId) : null;
ExternalCallResult? result = null;
Exception? thrown = null;
try
@@ -1223,7 +1451,7 @@ public class ScriptRuntimeContext
{
var elapsedMs = (int)((Stopwatch.GetTimestamp() - startTicks)
* 1000d / Stopwatch.Frequency);
- EmitCallAudit(systemName, methodName, occurredAtUtc, elapsedMs, result, thrown, parameters);
+ EmitCallAudit(systemName, methodName, occurredAtUtc, elapsedMs, result, thrown, parameters, stepId);
}
}
@@ -1610,6 +1838,18 @@ public class ScriptRuntimeContext
/// row. Any exception thrown by the writer is logged and swallowed —
/// audit-write failures must never abort the user-facing action.
///
+ /// External system name.
+ /// Method invoked on it.
+ /// When the call started.
+ /// How long it took.
+ /// The call result, when one was produced.
+ /// The exception the call threw, if any.
+ /// The call arguments.
+ ///
+ /// Step logs (design 2026-09-09 D6): the PRE-MINTED row id also opened as
+ /// the ambient , so the log lines produced during the call name
+ /// this row. Null (untraced) mints a fresh id as before.
+ ///
private void EmitCallAudit(
string systemName,
string methodName,
@@ -1617,7 +1857,8 @@ public class ScriptRuntimeContext
int durationMs,
ExternalCallResult? result,
Exception? thrown,
- IReadOnlyDictionary? parameters)
+ IReadOnlyDictionary? parameters,
+ Guid? eventId = null)
{
if (_auditWriter == null)
{
@@ -1628,7 +1869,7 @@ public class ScriptRuntimeContext
try
{
evt = BuildCallAuditEvent(
- systemName, methodName, occurredAtUtc, durationMs, result, thrown, parameters);
+ systemName, methodName, occurredAtUtc, durationMs, result, thrown, parameters, eventId);
}
catch (Exception buildEx)
{
@@ -1687,7 +1928,8 @@ public class ScriptRuntimeContext
int durationMs,
ExternalCallResult? result,
Exception? thrown,
- IReadOnlyDictionary? parameters)
+ IReadOnlyDictionary? parameters,
+ Guid? eventId = null)
{
// Status: Delivered on a Success result; Failed otherwise (the
// ExternalSystemClient already maps HTTP non-2xx + transient
@@ -1728,6 +1970,8 @@ public class ScriptRuntimeContext
channel: AuditChannel.ApiOutbound,
kind: AuditKind.ApiCall,
status: status,
+ // Step logs (D6): the id the caller already published as the ambient step.
+ eventId: eventId,
occurredAtUtc: DateTime.SpecifyKind(occurredAtUtc, DateTimeKind.Utc),
// Outbound channel: per the Audit Log Actor-column spec the actor
// is the calling script. Null when no single script owns the call
diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs
index ed71e6d0..ee485e09 100644
--- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs
+++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs
@@ -74,6 +74,22 @@ public sealed class TraceCapturingLogger : ILogger
_ => "error",
};
- _sink.Runtime(name, formatter(state, exception), exception);
+ string message;
+ try
+ {
+ message = formatter(state, exception);
+ }
+ catch
+ {
+ // Deliberate swallow: formatting is the CALLER's code, and a great many of the entries
+ // captured here are the runtime's own best-effort "audit write failed" warnings logged
+ // from inside a catch block. A throwing formatter escaping this decorator would replace
+ // the original failure with a formatting exception on a path whose whole contract is
+ // that it never throws. The line is dropped; the inner logger already saw (or refused)
+ // it above, unchanged.
+ return;
+ }
+
+ _sink.Runtime(name, message, exception);
}
}
diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs
index 267e6a70..914847ff 100644
--- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs
+++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptRuntimeContextTraceEmissionTests.cs
@@ -145,7 +145,8 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
IExternalSystemClient? externalSystemClient = null,
IDatabaseGateway? databaseGateway = null,
ICachedCallTelemetryForwarder? cachedForwarder = null,
- StoreAndForwardService? storeAndForward = null)
+ StoreAndForwardService? storeAndForward = null,
+ int maxLogLinesPerRun = 200)
=> new(
instanceActor, NewLibrary(),
currentCallDepth: 0, maxCallDepth: 10, askTimeout: TimeSpan.FromSeconds(5),
@@ -155,7 +156,8 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
siteId: "site-a", sourceScript: "ScriptActor:A", auditWriter: writer,
cachedForwarder: cachedForwarder,
executionId: executionId, parentExecutionId: parentExecutionId, sourceNode: "node-a",
- isTraced: traced, traceCollector: collector);
+ isTraced: traced, traceCollector: collector,
+ maxLogLinesPerRun: maxLogLinesPerRun);
[Fact]
public async Task SetAttribute_WhenTraced_EmitsAttributeWriteRow_AndPassesTraceOnCommand()
@@ -556,4 +558,268 @@ public class ScriptRuntimeContextTraceEmissionTests : TestKit
var written = Assert.Single(writer.Events);
Assert.Equal(AuditKind.ApiCall, Row(written).Kind);
}
+
+ // ---- Step logs: the Log global and runtime-line attribution (design 2026-09-09 D4-D7) ----
+
+ /// Fails every write so the context's own best-effort "write failed" warning fires —
+ /// the runtime line test (c) needs a genuine _logger.LogWarning inside a step body.
+ private sealed class ThrowingAuditWriter : IAuditWriter
+ {
+ public Task WriteAsync(AuditEvent evt, CancellationToken ct = default)
+ => throw new InvalidOperationException("writer down");
+ }
+
+ [Fact]
+ public void Log_WhenTraced_EmitsOneScriptLogRow_ToTheCollectorAndTheWriter()
+ {
+ var writer = new CapturingAuditWriter();
+ var collector = new FlowTraceCollector();
+ var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector);
+
+ ctx.Log.Info("x");
+
+ var evt = Assert.Single(writer.Events);
+ Assert.Same(evt, Assert.Single(collector.Snapshot()));
+ var row = Row(evt);
+ Assert.Equal(AuditChannel.ScriptTrace, row.Channel);
+ Assert.Equal(AuditKind.ScriptLog, row.Kind);
+ Assert.Equal(AuditStatus.Delivered, row.Status);
+ Assert.Equal("x", row.RequestSummary);
+ Assert.Equal(ctx.ExecutionId, row.ExecutionId);
+ Assert.Equal("site-a", row.SourceSiteId);
+ Assert.Equal("node-a", evt.SourceNode);
+ Assert.Equal(InstanceName, row.SourceInstanceId);
+ // Same bare script name the ScriptRun anchor row carries, so the builder's fallback matches.
+ Assert.Equal("A", evt.Target);
+ var extra = ScriptTraceExtra.TryParse(row.Extra)!;
+ Assert.Equal("info", extra.LogLevel);
+ Assert.Equal("script", extra.LogSource);
+ Assert.Null(extra.StepEventId);
+ Assert.Equal(1, extra.Seq);
+ }
+
+ [Fact]
+ public void Log_WhenNotTraced_ReachesNeitherTheWriterNorTheCollector()
+ {
+ var writer = new CapturingAuditWriter();
+ var collector = new FlowTraceCollector();
+ var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: false, collector);
+
+ ctx.Log.Info("x");
+ ctx.Log.Error("boom", new InvalidOperationException("e"));
+ ctx.Log.FlushDropped();
+
+ Assert.Empty(writer.Events);
+ Assert.Equal(0, collector.Count);
+ Assert.False(collector.LogsTruncated);
+ }
+
+ [Fact]
+ public async Task RuntimeWarning_InsideATracedWrite_IsAttributedToThatWriteStep()
+ {
+ var probe = CreateTestProbe();
+ var collector = new FlowTraceCollector();
+ // The throwing writer makes EmitTrace log its best-effort "write failed" warning while the
+ // AttributeWrite step scope is open — exactly the runtime line D6 exists to attribute.
+ //
+ // It also PINS THE ANTI-RECURSION PROPERTY: EmitLog's own write fails against this writer
+ // too, so its "log-line write failed" warning must go to the UNDECORATED logger. Routed
+ // through the capturing decorator instead, each warning would emit another row whose write
+ // fails again — an unbounded loop, and this test would hang or blow the row count rather
+ // than see exactly one ScriptLog row.
+ var ctx = CreateContext(probe.Ref, new ThrowingAuditWriter(), traced: true, collector);
+
+ var call = ctx.SetAttribute("Setpoint", "42");
+ var cmd = probe.ExpectMsg(TimeSpan.FromSeconds(5));
+ probe.Reply(new SetStaticAttributeResponse(cmd.CorrelationId, InstanceName, "Setpoint", true, null, DateTimeOffset.UtcNow));
+ await call;
+
+ var rows = collector.Snapshot();
+ var write = rows.Single(e => Row(e).Kind == AuditKind.AttributeWrite);
+ var log = rows.Single(e => Row(e).Kind == AuditKind.ScriptLog);
+ var extra = ScriptTraceExtra.TryParse(Row(log).Extra)!;
+ Assert.Equal("runtime", extra.LogSource);
+ Assert.Equal("warn", extra.LogLevel);
+ Assert.Equal(write.EventId, extra.StepEventId);
+ }
+
+ [Fact]
+ public void Log_WithException_CarriesTheMessageAndTheFullDetail()
+ {
+ var writer = new CapturingAuditWriter();
+ var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, new FlowTraceCollector());
+
+ ctx.Log.Warn("m", new InvalidOperationException("e"));
+
+ var row = Row(Assert.Single(writer.Events));
+ Assert.Equal("m", row.RequestSummary);
+ Assert.Equal("e", row.ErrorMessage);
+ Assert.StartsWith("System.InvalidOperationException", row.ErrorDetail);
+ Assert.Equal("warn", ScriptTraceExtra.TryParse(row.Extra)!.LogLevel);
+ }
+
+ [Fact]
+ public async Task LogRows_RideTheLowPriorityLane_SoStepRowsKeepTheirReserve()
+ {
+ var probe = CreateTestProbe();
+ var writer = new CapturingAuditWriter();
+ // Reserve (50) + 1 => exactly one low-priority slot, while step rows keep the full cap.
+ var collector = new FlowTraceCollector(maxEvents: FlowTraceCollector.LowPriorityReserveEvents + 1);
+ var ctx = CreateContext(probe.Ref, writer, traced: true, collector);
+
+ ctx.Log.Info("first");
+ ctx.Log.Info("second");
+
+ Assert.Single(collector.Snapshot());
+ Assert.True(collector.LogsTruncated);
+ Assert.False(collector.Truncated);
+
+ var call = ctx.SetAttribute("Setpoint", "42");
+ var cmd = probe.ExpectMsg(TimeSpan.FromSeconds(5));
+ probe.Reply(new SetStaticAttributeResponse(cmd.CorrelationId, InstanceName, "Setpoint", true, null, DateTimeOffset.UtcNow));
+ await call;
+
+ Assert.Equal(2, collector.Count);
+ Assert.Contains(collector.Snapshot(), e => Row(e).Kind == AuditKind.AttributeWrite);
+ }
+
+ [Fact]
+ public void FlushDropped_EmitsTheClosingRow_OnceThePerRunCapIsExceeded()
+ {
+ var writer = new CapturingAuditWriter();
+ var collector = new FlowTraceCollector();
+ var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector, maxLogLinesPerRun: 2);
+
+ ctx.Log.Info("1");
+ ctx.Log.Info("2");
+ ctx.Log.Info("3");
+ ctx.Log.FlushDropped();
+
+ var rows = collector.Snapshot();
+ Assert.Equal(3, rows.Count);
+ var closing = Row(rows[^1]);
+ var extra = ScriptTraceExtra.TryParse(closing.Extra)!;
+ Assert.Equal("warn", extra.LogLevel);
+ Assert.Equal("runtime", extra.LogSource);
+ Assert.Contains("1 line(s) dropped", closing.RequestSummary);
+ }
+
+ ///
+ /// Review I1: the sync ExternalSystem.Call pre-mints its ApiCall row id and
+ /// publishes it as the ambient step, so a warning logged while the call is in flight names
+ /// that node. Provoked the same way as the write case — a writer that throws makes the
+ /// helper's own best-effort "audit write threw" warning fire inside the scope.
+ ///
+ [Fact]
+ public async Task RuntimeWarning_InsideATracedExternalCall_IsAttributedToTheApiCallStep()
+ {
+ var collector = new FlowTraceCollector();
+ var ctx = CreateContext(CreateTestProbe().Ref, new ThrowingAuditWriter(), traced: true, collector,
+ externalSystemClient: SyncClient(new ExternalCallResult(true, "{}", null)).Object);
+
+ var result = await ctx.ExternalSystem.Call("ERP", "GetOrder");
+
+ Assert.True(result.Success);
+ var rows = collector.Snapshot();
+ var call = rows.Single(e => Row(e).Kind == AuditKind.ApiCall);
+ var log = rows.Single(e => Row(e).Kind == AuditKind.ScriptLog);
+ var extra = ScriptTraceExtra.TryParse(Row(log).Extra)!;
+ Assert.Equal("runtime", extra.LogSource);
+ Assert.Equal(call.EventId, extra.StepEventId);
+ }
+
+ ///
+ /// Review I1: the step scope is gated on the run's TRACE FLAG, not on the presence of an
+ /// inline collector — a traced run without one still writes durable ScriptLog rows that
+ /// have to name their step.
+ ///
+ [Fact]
+ public async Task TracedExternalCall_WithoutACollector_StillNamesTheApiCallStep()
+ {
+ var writer = new CapturingAuditWriter();
+ var ctx = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector: null,
+ externalSystemClient: SyncClient(new ExternalCallResult(true, "{}", null)).Object);
+
+ await ctx.ExternalSystem.Call("ERP", "GetOrder");
+ ctx.Log.Info("after the call, outside any scope");
+
+ var call = writer.Events.Single(e => Row(e).Kind == AuditKind.ApiCall);
+ // The line above is outside the scope, so it falls back to the anchor; what this pins is
+ // that the call's row id was minted and published at all on a collector-less traced run.
+ Assert.NotEqual(Guid.Empty, call.EventId);
+ var log = writer.Events.Single(e => Row(e).Kind == AuditKind.ScriptLog);
+ Assert.Null(ScriptTraceExtra.TryParse(Row(log).Extra)!.StepEventId);
+ }
+
+ ///
+ /// Review I2 (design §5): an inline shared script SHARES its caller's
+ /// — one counter, one anchor. Its lines therefore carry the PARENT run's ExecutionId and
+ /// land on the parent's ScriptRun node, even though its own step rows chain under its own
+ /// execution.
+ ///
+ [Fact]
+ public void SharedScriptChild_SharesTheCallersLogger_ExecutionIdAndCap()
+ {
+ var writer = new CapturingAuditWriter();
+ var collector = new FlowTraceCollector();
+ var parent = CreateContext(CreateTestProbe().Ref, writer, traced: true, collector, maxLogLinesPerRun: 2);
+ var child = parent.CreateChildContextForSharedScript(1);
+
+ Assert.Same(parent.Log, child.Log);
+ Assert.NotEqual(parent.ExecutionId, child.ExecutionId);
+
+ parent.Log.Info("from the caller");
+ child.Log.Info("shared");
+ // Third line from either side is over the SHARED cap of 2.
+ child.Log.Info("dropped");
+ parent.Log.Info("also dropped");
+
+ var rows = collector.Snapshot();
+ Assert.Equal(2, rows.Count);
+ Assert.All(rows, e => Assert.Equal(parent.ExecutionId, Row(e).ExecutionId));
+ Assert.Equal(["from the caller", "shared"], rows.Select(e => Row(e).RequestSummary));
+
+ parent.Log.FlushDropped();
+ Assert.Contains("2 line(s) dropped", Row(collector.Snapshot()[^1]).RequestSummary);
+ }
+
+ ///
+ /// Review item 4: step scopes NEST — the batch leg's lines name the batch row, the wait leg's
+ /// name the wait row, and both unwind so a later line falls back to the run anchor. The
+ /// throwing writer is again what provokes a runtime line inside each leg.
+ ///
+ [Fact]
+ public async Task NestedStepScopes_AttributeEachLegSeparately_AndUnwind()
+ {
+ var probe = CreateTestProbe();
+ var collector = new FlowTraceCollector();
+ var ctx = CreateContext(probe.Ref, new ThrowingAuditWriter(), traced: true, collector);
+
+ var call = ctx.WriteBatchAndWait(
+ new Dictionary { ["Recipe"] = "R-17" },
+ "Trigger", "1", "Ack", "1", TimeSpan.FromSeconds(3));
+
+ var batchReq = probe.ExpectMsg(TimeSpan.FromSeconds(5));
+ probe.Reply(new WriteAttributeBatchResponse(batchReq.CorrelationId, true, null));
+ var waitReq = probe.ExpectMsg(TimeSpan.FromSeconds(5));
+ probe.Reply(new WaitForAttributeResponse(waitReq.CorrelationId, Matched: true, "1", "Good", TimedOut: false));
+ Assert.True(await call);
+
+ // Both scopes have unwound by the time the run continues.
+ ctx.Log.Info("after both legs");
+
+ var rows = collector.Snapshot();
+ var write = rows.Single(e => Row(e).Kind == AuditKind.AttributeWrite);
+ var wait = rows.Single(e => Row(e).Kind == AuditKind.AttributeWait);
+ Assert.NotEqual(write.EventId, wait.EventId);
+
+ var logs = rows.Where(e => Row(e).Kind == AuditKind.ScriptLog)
+ .Select(e => ScriptTraceExtra.TryParse(Row(e).Extra)!)
+ .ToList();
+ Assert.Equal(3, logs.Count);
+ Assert.Equal(write.EventId, logs[0].StepEventId);
+ Assert.Equal(wait.EventId, logs[1].StepEventId);
+ Assert.Null(logs[2].StepEventId);
+ Assert.Equal(["runtime", "runtime", "script"], logs.Select(l => l.LogSource));
+ }
}
diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs
index 806e53c8..657fb1ec 100644
--- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs
+++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs
@@ -156,6 +156,27 @@ public class TraceCapturingLoggerTests
Assert.Throws(() => new TraceCapturingLogger(new RecordingLogger(), null!));
}
+ [Fact]
+ public void AThrowingFormatter_IsSwallowed_AndDropsOnlyThatLine()
+ {
+ // Review M3. Most of what this decorator captures is the runtime's own best-effort
+ // "audit write failed" warnings, logged from INSIDE a catch block: a formatter exception
+ // escaping here would replace the original failure with a formatting one on a path whose
+ // contract is that it never throws. The inner logger is disabled for this level so the
+ // decorator's OWN formatter call is the only one under test.
+ var (logger, inner, rows) = Make(innerMinimum: LogLevel.Critical);
+
+ logger.Log(LogLevel.Warning, new EventId(0), "state", null,
+ (_, _) => throw new InvalidOperationException("formatter broke"));
+
+ Assert.Empty(rows);
+ Assert.Empty(inner.Entries);
+
+ // …and the decorator keeps working for the next line.
+ logger.LogWarning("still alive");
+ Assert.Equal("still alive", Assert.Single(rows).Message);
+ }
+
[Fact]
public void BeginScope_DelegatesToTheInnerLogger()
{