dohertj2/ScadaBridge
1
0
Fork 0
Code Issues 2 Pull Requests Actions Packages Projects Releases Wiki Activity

feat(site-runtime): ScriptRuntimeContext emits ScriptTrace AttributeWrite/AttributeWait rows and inherits the Trace flag

Browse Source 
Flow Debugger (design 2026-09-05 §5.1/§5.2): the context is the single funnel for
SetAttribute / WriteBatchAndWait / WaitInternal, so it emits the write/wait rows (collector
first, then the best-effort IAuditWriter whose redactor applies the payload cap), stamps
Trace on SetStaticAttributeCommand and ScriptCallRequest, and hands the flag + sink to the
inline CallShared child context. Untraced contexts emit nothing (pinned).

Claude-Session: https://claude.ai/code/session_01GSLkkHKz9JrAtmJjmQK3cP
This commit is contained in:
Joseph Doherty
2026-09-05 23:43:32 -04:00
parent 23157d2bcf
commit 93489cd7a2
2 changed files with 393 additions and 9 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs
+187 -9
View File
@@ -12,6 +12,7 @@ using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution;
using ZB.MOM.WW.ScadaBridge.Commons.Messages.Streaming;
using ZB.MOM.WW.ScadaBridge.Commons.Types;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums;
using ZB.MOM.WW.ScadaBridge.Commons.Types.Scripts;
using AuditEvent = ZB.MOM.WW.Audit.AuditEvent;
@@ -164,6 +165,20 @@ public class ScriptRuntimeContext
/// </summary>
private readonly Guid? _parentExecutionId;
/// <summary>
/// Flow Debugger (design 2026-09-05 §5.2): true when this run is traced — the
/// <c>Trace</c> flag rode in beside <c>ParentExecutionId</c> on the spawning message
/// (or <c>ApiMethod.TraceAllCalls</c> set it at the root). Gates every
/// <c>ScriptTrace</c> row this context emits and is inherited by nested runs.
/// </summary>
private readonly bool _isTraced;
/// <summary>
/// Flow Debugger (design §5.4): the per-run inline sink the launcher attaches to
/// <c>ScriptCallResult.TraceEvents</c>. Null when untraced.
/// </summary>
private readonly FlowTraceCollector? _traceCollector;
/// <summary>
/// Initializes a new script runtime context with all dependencies for script
/// execution, external system calls, database access, and notification delivery.
@@ -213,6 +228,8 @@ public class ScriptRuntimeContext
/// <see cref="CancellationToken.None"/> for callers / tests that do not
/// thread one — those waits are bounded only by their own timeout.
/// </param>
/// <param name="isTraced">Flow Debugger trace flag — see design 2026-09-05 §5.2. Defaults to untraced.</param>
/// <param name="traceCollector">Flow Debugger per-run inline trace sink (design §5.4); null when untraced.</param>
public ScriptRuntimeContext(
IActorRef instanceActor,
SharedScriptLibrary sharedScriptLibrary,
@@ -234,7 +251,9 @@ public class ScriptRuntimeContext
Guid? parentExecutionId = null,
string? sourceNode = null,
ISiteEventLogger? siteEventLogger = null,
CancellationToken scriptTimeoutToken = default)
CancellationToken scriptTimeoutToken = default,
bool isTraced = false,
FlowTraceCollector? traceCollector = null)
{
_instanceActor = instanceActor;
_sharedScriptLibrary = sharedScriptLibrary;
@@ -266,8 +285,13 @@ public class ScriptRuntimeContext
// WaitForAttribute (spec §4.3): default(CancellationToken) == None when
// not threaded in — the WaitAsync Ask is then bounded only by its own timeout.
_scriptTimeoutToken = scriptTimeoutToken;
_isTraced = isTraced;
_traceCollector = traceCollector;
}
/// <summary>Flow Debugger (design 2026-09-05 §5.2): whether this run emits <c>ScriptTrace</c> rows.</summary>
public bool IsTraced => _isTraced;
/// <summary>
/// This run's own per-execution id. Exposed so a
/// nested <c>Scripts.CallShared</c> can record it as the spawned shared
@@ -322,7 +346,69 @@ public class ScriptRuntimeContext
// WaitForAttribute (spec §4.3): an inline shared-script call shares the
// parent run's execution-timeout token so a WaitAsync inside the shared
// script is bounded by the SAME script deadline.
scriptTimeoutToken: _scriptTimeoutToken);
scriptTimeoutToken: _scriptTimeoutToken,
// 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);
}
/// <summary>
/// Flow Debugger (design 2026-09-05 §5.1): emits one <c>ScriptTrace</c> audit row for a
/// traced run — into the inline collector first (so a routed call can return it) and
/// then through the best-effort <see cref="IAuditWriter"/>. No-op when untraced, never
/// 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.
/// </summary>
private void EmitTrace(
AuditKind kind, AuditStatus status, string target, DateTime startedUtc, int durationMs,
string? input, string? output, string? error, ScriptTraceExtra? extra)
{
if (!_isTraced) return;
AuditEvent evt;
try
{
evt = ScadaBridgeAuditEventFactory.Create(
AuditChannel.ScriptTrace, kind, status,
occurredAtUtc: DateTime.SpecifyKind(startedUtc, DateTimeKind.Utc),
actor: _sourceScript, target: target, sourceNode: _sourceNode,
executionId: _executionId, parentExecutionId: _parentExecutionId,
sourceSiteId: string.IsNullOrEmpty(_siteId) ? null : _siteId,
sourceInstanceId: _instanceName, sourceScript: _sourceScript,
durationMs: durationMs, errorMessage: error,
requestSummary: input, responseSummary: output,
extra: extra?.ToJson());
}
catch (Exception ex)
{
_logger.LogWarning(ex, "Flow trace event build failed for {Kind}", kind);
return;
}
_traceCollector?.Add(evt);
if (_auditWriter is null) return;
try
{
var t = _auditWriter.WriteAsync(evt, CancellationToken.None);
if (!t.IsCompletedSuccessfully)
{
_ = t.ContinueWith(
x => _logger.LogWarning(x.Exception, "Flow trace write failed for {Kind}", kind),
TaskContinuationOptions.OnlyOnFaulted);
}
}
catch (Exception ex)
{
_logger.LogWarning(ex, "Flow trace write failed for {Kind}", kind);
}
}
/// <summary>Serialises a small trace payload; null on failure (best-effort, like the audit helpers).</summary>
private static string? TraceJson(object? value)
{
if (value is null) return null;
try { return JsonSerializer.Serialize(value, ScriptTraceExtra.JsonOptions); }
catch (Exception) { return null; }
}
/// <summary>
@@ -477,9 +563,12 @@ public class ScriptRuntimeContext
cid, _instanceName, name, targetValueEncoded, predicate, timeout, DateTimeOffset.UtcNow,
requireGoodQuality);
var startedUtc = DateTime.UtcNow;
var sw = _isTraced ? Stopwatch.StartNew() : null;
WaitForAttributeResponse response;
try
{
return await _instanceActor.Ask<WaitForAttributeResponse>(
response = await _instanceActor.Ask<WaitForAttributeResponse>(
req, timeout + _askTimeout, _scriptTimeoutToken);
}
catch (AskTimeoutException)
@@ -491,9 +580,47 @@ public class ScriptRuntimeContext
// OperationCanceledException / TaskCanceledException from the
// script-deadline token are deliberately NOT caught here: they must
// propagate to abort the script (§4.3).
return new WaitForAttributeResponse(
response = new WaitForAttributeResponse(
cid, Matched: false, null, null, TimedOut: true);
}
catch (OperationCanceledException)
{
// Script deadline hit mid-wait: record the cancelled wait for a traced run, then
// let the cancellation propagate exactly as before (§4.3).
if (sw is not null)
{
EmitTrace(AuditKind.AttributeWait, AuditStatus.Failed, name, startedUtc,
(int)sw.ElapsedMilliseconds, null, null, "Wait cancelled by the script deadline",
new ScriptTraceExtra
{
WaitAttribute = name, WaitTarget = targetValueEncoded ?? (predicate is null ? null : "<predicate>"),
WaitTimeoutMs = (int)timeout.TotalMilliseconds, WaitOutcome = "cancelled",
});
}
throw;
}
if (sw is not null)
{
var outcome = response.Matched ? "satisfied" : response.TimedOut ? "timeout" : "error";
var observed = AttributeValueCodec.Encode(response.Value);
EmitTrace(AuditKind.AttributeWait,
response.Matched ? AuditStatus.Delivered : AuditStatus.Failed,
name, startedUtc, (int)sw.ElapsedMilliseconds,
input: TraceJson(new { attribute = name, target = targetValueEncoded, timeoutMs = (int)timeout.TotalMilliseconds, requireGoodQuality }),
output: TraceJson(new { matched = response.Matched, timedOut = response.TimedOut, value = observed, quality = response.Quality }),
error: response.Matched ? null : response.ErrorMessage ?? (response.TimedOut ? $"Wait for '{name}' timed out after {timeout.TotalSeconds}s" : null),
extra: new ScriptTraceExtra
{
WaitAttribute = name,
WaitTarget = targetValueEncoded ?? (predicate is null ? null : "<predicate>"),
WaitTimeoutMs = (int)timeout.TotalMilliseconds,
WaitOutcome = outcome,
ObservedValue = observed,
});
}
return response;
}
/// <summary>
@@ -519,11 +646,41 @@ public class ScriptRuntimeContext
// ExecutionId as the write's originating execution. The Instance Actor
// carries it onto the published AttributeValueChanged, so an alarm this
// write trips records this run as the on-trigger script's parent.
SourceExecutionId: _executionId);
SourceExecutionId: _executionId,
// Flow Debugger (design §5.2/§5.3): a traced run's write arms the instance
// actor's echo stamp and rides onto the published AttributeValueChanged.
Trace: _isTraced);
// Ask — mutation serialized through the Instance Actor mailbox; the reply
// carries the device-write outcome for data-connected attributes.
var response = await _instanceActor.Ask<SetStaticAttributeResponse>(command, _askTimeout);
var startedUtc = DateTime.UtcNow;
var sw = _isTraced ? Stopwatch.StartNew() : null;
SetStaticAttributeResponse response;
try
{
// Ask — mutation serialized through the Instance Actor mailbox; the reply
// carries the device-write outcome for data-connected attributes.
response = await _instanceActor.Ask<SetStaticAttributeResponse>(command, _askTimeout);
}
catch (Exception ex) when (sw is not null)
{
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)] });
throw;
}
if (sw is not null)
{
EmitTrace(AuditKind.AttributeWrite,
response.Success ? AuditStatus.Delivered : AuditStatus.Failed,
attributeName, startedUtc, (int)sw.ElapsedMilliseconds,
input: TraceJson(new { attribute = attributeName, value }),
output: null,
error: response.ErrorMessage,
extra: new ScriptTraceExtra
{
Writes = [new AttributeWriteDetail(attributeName, value, response.Success, response.ErrorMessage)],
});
}
if (!response.Success)
{
@@ -560,9 +717,28 @@ public class ScriptRuntimeContext
// 35s: the InstanceActor's DCL Ask is internally bounded at 30s, so allow a small
// margin so the DCL's own typed failure/timeout reply is the one we observe rather
// than an AskTimeoutException here. Honors the script execution-timeout token.
var startedUtc = DateTime.UtcNow;
var sw = _isTraced ? Stopwatch.StartNew() : null;
var batchResp = await _instanceActor.Ask<WriteAttributeBatchResponse>(
batchReq, TimeSpan.FromSeconds(35), _scriptTimeoutToken);
if (sw is not null)
{
// Flow Debugger (design §5.1): one AttributeWrite row per batch — every value plus the
// trigger — with the batch's single outcome on each write.
var writes = encodedValues
.Select(kv => new AttributeWriteDetail(kv.Key, kv.Value, batchResp.Success, batchResp.ErrorMessage))
.Append(new AttributeWriteDetail(triggerAttr, triggerEncoded, batchResp.Success, batchResp.ErrorMessage))
.ToList();
EmitTrace(AuditKind.AttributeWrite,
batchResp.Success ? AuditStatus.Delivered : AuditStatus.Failed,
triggerAttr, startedUtc, (int)sw.ElapsedMilliseconds,
input: TraceJson(new { values = encodedValues, trigger = triggerAttr, triggerValue = triggerEncoded }),
output: null,
error: batchResp.ErrorMessage,
extra: new ScriptTraceExtra { TriggerAttribute = triggerAttr, TriggerValue = triggerEncoded, Writes = writes });
}
if (!batchResp.Success)
throw new InvalidOperationException(
$"WriteBatchAndWait write failed: {batchResp.ErrorMessage}");
@@ -605,7 +781,9 @@ public class ScriptRuntimeContext
// So A → CallScript(B) yields B.ParentExecutionId == A.ExecutionId,
// building a true multi-level execution tree rather than flattening
// every nested call under the original inbound spawner.
ParentExecutionId: _executionId);
ParentExecutionId: _executionId,
// Flow Debugger (design §5.2): nested runs inherit the trace flag.
Trace: _isTraced);
// Ask the Instance Actor, which routes to the appropriate Script Actor
var result = await _instanceActor.Ask<ScriptCallResult>(request, _askTimeout);