Merge R2-03 Virtual-Tag failure quality (arch-review round 2) [PR #430]
v2-ci / build (push) Successful in 4m2s
v2-ci / unit-tests (push) Failing after 8m20s

Findings 02/S13 (VT failure/timeout degrades node to Bad quality, no stale-Good
forever), 02/S12 (evaluator retry-once on disposed-race), 02/P7 (compile-cache
clear gated on changed expression set). T11/T12 deferred. STATUS.md conflict
resolved additively. Build clean.
This commit is contained in:
Joseph Doherty
2026-07-13 10:20:43 -04:00
9 changed files with 589 additions and 88 deletions
@@ -18,6 +18,19 @@ namespace ZB.MOM.WW.OtOpcUa.Host.Engines;
/// fan-out between actors is owned by <c>DependencyMuxActor</c>, not by the eval engine.
/// Cycle detection + cascade ordering live in <see cref="VirtualTagEngine"/>; this adapter
/// stays single-tag scoped to keep <see cref="VirtualTagActor"/>'s message loop simple.
///
/// <para>
/// 02/S12 — the apply-boundary <see cref="ClearCompiledScripts"/> (driven by the host actor per
/// deploy generation) disposes cached evaluators while unchanged children may still be evaluating.
/// A clear landing between this adapter's <c>GetOrCompile</c> and the run's disposed guard would
/// otherwise surface as a spurious <c>Failure</c>. The compiled path is therefore retry-safe: an
/// <see cref="ObjectDisposedException"/> from an in-flight evaluation re-fetches (recompiling the
/// same source into the current cache generation) and retries once. A second disposal mid-retry
/// (two applies inside one evaluation — not a realistic cadence) falls through to the failure path.
/// Residual (accepted, bounded to one generation): a stopping child can recompile its stale source
/// into the fresh cache for one generation; P7's expression-set gate means no-op redeploys no
/// longer open this window at all.
/// </para>
/// </summary>
public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCacheOwner, IDisposable
{
@@ -63,27 +76,6 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac
: VirtualTagEvalResult.Ok(null);
}
ScriptEvaluator<VirtualTagContext, object?> evaluator;
try
{
evaluator = _cache.GetOrCompile(expression);
}
catch (CompilationErrorException ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: Roslyn compile failed", virtualTagId);
return VirtualTagEvalResult.Failure($"compile error: {ex.Message}");
}
catch (ScriptSandboxViolationException ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: sandbox violation", virtualTagId);
return VirtualTagEvalResult.Failure($"sandbox violation: {ex.Message}");
}
catch (Exception ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: compile threw", virtualTagId);
return VirtualTagEvalResult.Failure($"compile failure: {ex.Message}");
}
var readCache = BuildReadCache(dependencies);
// Per-evaluation script logger: bind both ScriptId and VirtualTagId from the virtual-tag id
// (in the live path the script id equals the virtual-tag id) so the Script-log page can
@@ -98,25 +90,71 @@ public sealed class RoslynVirtualTagEvaluator : IVirtualTagEvaluator, IScriptCac
virtualTagId, path),
logger: scriptLog);
try
// 02/S12: fetch + run inside a bounded loop so an ObjectDisposedException caused by a concurrent
// apply-boundary ClearCompiledScripts (which disposed the evaluator between GetOrCompile and the
// run's disposed guard) re-fetches and retries exactly once. The loop runs at most twice — the
// retry catch only matches attempt == 0.
for (var attempt = 0; ; attempt++)
{
// Route through TimedScriptEvaluator (Task.Run + WaitAsync): a raw CancellationToken can't
// interrupt a CPU-bound/infinite-loop script (Roslyn scripts don't poll it), so the previous
// CTS-only path let one runaway script hang this actor forever. WaitAsync returns control when
// the wall-clock budget fires regardless of whether the inner task completes (the orphaned
// thread is the documented, accepted trade-off — TimedScriptEvaluator remarks).
var timed = new TimedScriptEvaluator<VirtualTagContext, object?>(evaluator, _runTimeout);
var raw = timed.RunAsync(context).GetAwaiter().GetResult();
return VirtualTagEvalResult.Ok(raw);
}
catch (ScriptTimeoutException)
{
return VirtualTagEvalResult.Failure($"script timed out after {_runTimeout.TotalSeconds:F1}s");
}
catch (Exception ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: script execution threw", virtualTagId);
return VirtualTagEvalResult.Failure($"script threw: {ex.Message}");
ScriptEvaluator<VirtualTagContext, object?> evaluator;
try
{
evaluator = _cache.GetOrCompile(expression);
}
catch (CompilationErrorException ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: Roslyn compile failed", virtualTagId);
return VirtualTagEvalResult.Failure($"compile error: {ex.Message}");
}
catch (ScriptSandboxViolationException ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: sandbox violation", virtualTagId);
return VirtualTagEvalResult.Failure($"sandbox violation: {ex.Message}");
}
catch (ObjectDisposedException)
{
// The cache itself is being torn down (this evaluator is disposing) — a fetch-time
// disposal is a shutdown signal, not the apply-boundary race, so never retry.
return VirtualTagEvalResult.Failure("evaluator disposed");
}
catch (Exception ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: compile threw", virtualTagId);
return VirtualTagEvalResult.Failure($"compile failure: {ex.Message}");
}
try
{
// Route through TimedScriptEvaluator (Task.Run + WaitAsync): a raw CancellationToken can't
// interrupt a CPU-bound/infinite-loop script (Roslyn scripts don't poll it), so the previous
// CTS-only path let one runaway script hang this actor forever. WaitAsync returns control when
// the wall-clock budget fires regardless of whether the inner task completes (the orphaned
// thread is the documented, accepted trade-off — TimedScriptEvaluator remarks).
var timed = new TimedScriptEvaluator<VirtualTagContext, object?>(evaluator, _runTimeout);
var raw = timed.RunAsync(context).GetAwaiter().GetResult();
return VirtualTagEvalResult.Ok(raw);
}
catch (ScriptTimeoutException)
{
return VirtualTagEvalResult.Failure($"script timed out after {_runTimeout.TotalSeconds:F1}s");
}
catch (ObjectDisposedException) when (!_disposed && attempt == 0)
{
// S12: the apply-boundary ClearCompiledScripts disposed the evaluator between our
// GetOrCompile and the run's disposed-guard. Re-fetch — GetOrCompile recompiles the same
// source into the CURRENT cache generation — and retry once. A second disposal mid-retry
// (two applies inside one evaluation) falls through to the failure path below.
continue;
}
catch (ObjectDisposedException)
{
return VirtualTagEvalResult.Failure("evaluator disposed during evaluation");
}
catch (Exception ex)
{
_logger.LogWarning(ex, "VirtualTag {Id}: script execution threw", virtualTagId);
return VirtualTagEvalResult.Failure($"script threw: {ex.Message}");
}
}
}
@@ -4,6 +4,7 @@ using Akka.Event;
using ZB.MOM.WW.OtOpcUa.Commons.Engines;
using ZB.MOM.WW.OtOpcUa.Commons.Messages.Logging;
using ZB.MOM.WW.OtOpcUa.Commons.Observability;
using ZB.MOM.WW.OtOpcUa.Commons.OpcUa;
using ZB.MOM.WW.OtOpcUa.Commons.Types;
namespace ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags;
@@ -12,15 +13,30 @@ namespace ZB.MOM.WW.OtOpcUa.Runtime.VirtualTags;
/// Wraps a single virtual-tag expression. Receives dependency-tag updates, recomputes the
/// expression via an injected <see cref="IVirtualTagEvaluator"/>, and emits an
/// <see cref="EvaluationResult"/> to the parent (the publish actor) whenever the value
/// actually changes. Script failures publish a Warning <see cref="ScriptLogEntry"/> on the
/// actually changes. Script failures publish a <see cref="ScriptLogEntry"/> on the
/// <c>script-logs</c> DPS topic so operators see the diagnostic in the live tail.
///
/// <para>
/// 02/S13 — a persistent script failure/timeout also degrades the node's OPC UA quality to
/// <see cref="OpcUaQuality.Bad"/> (carrying the last-known value), published <b>once per
/// transition</b> (Good→Bad) and gated on every declared dependency having arrived at least once
/// — so a broken script no longer serves its last Good value forever, and a fresh/respawned
/// multi-dep script does not flash Bad during deploy warm-up. Recovery to a Good value clears the
/// Bad state and is force-published even when the value equals the pre-failure value.
/// </para>
/// </summary>
public sealed class VirtualTagActor : ReceiveActor
{
public const string ScriptLogsTopic = "script-logs";
public sealed record DependencyValueChanged(string TagId, object? Value, DateTime TimestampUtc);
public sealed record EvaluationResult(string VirtualTagId, object? Value, DateTime TimestampUtc, CorrelationId Correlation);
/// <summary>Result emitted to the parent (the host bridge). <paramref name="Quality"/> carries the
/// OPC UA quality the node should read: <see cref="OpcUaQuality.Good"/> for a fresh computed value,
/// <see cref="OpcUaQuality.Bad"/> when the script failed/timed out (02/S13) — in which case
/// <paramref name="Value"/> is the last-known value (or null if none). Defaulting to Good keeps
/// every existing construction site source-compatible.</summary>
public sealed record EvaluationResult(string VirtualTagId, object? Value, DateTime TimestampUtc, CorrelationId Correlation, OpcUaQuality Quality = OpcUaQuality.Good);
private readonly string _virtualTagId;
private readonly string _scriptId;
@@ -34,6 +50,9 @@ public sealed class VirtualTagActor : ReceiveActor
private bool _hasLastValue;
private object? _lastValue;
// 02/S13: true once a Bad EvaluationResult has been published and not yet cleared by a Good
// recovery. Gates Bad publishes to once-per-transition and force-publishes the recovery value.
private bool _lastPublishedBad;
/// <summary>Factory method to create Props for a VirtualTagActor.</summary>
/// <param name="virtualTagId">Unique identifier for the virtual tag.</param>
@@ -115,27 +134,28 @@ public sealed class VirtualTagActor : ReceiveActor
catch (Exception ex)
{
_log.Warning(ex, "VirtualTag {Id}: evaluator threw", _virtualTagId);
OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair<string, object?>("outcome", "fail"));
PublishLog("Error", $"evaluator threw: {ex.Message}");
OnEvaluationFailed($"evaluator threw: {ex.Message}", "Error", msg.TimestampUtc);
return;
}
if (!result.Success)
{
OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair<string, object?>("outcome", "fail"));
PublishLog("Warning", result.Reason ?? "evaluator failure");
OnEvaluationFailed(result.Reason ?? "evaluator failure", "Warning", msg.TimestampUtc);
return;
}
// Skip no-change results. Real evaluator returns Ok(value); Null returns NoChange — both
// safe because Null never produces a fresh value.
// safe because Null never produces a fresh value. NoChange is "no fresh value", NOT a recovery,
// so it must stay above the dedup and must NOT clear _lastPublishedBad.
if (ReferenceEquals(result, VirtualTagEvalResult.NoChange))
{
OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair<string, object?>("outcome", "skip"));
return;
}
if (_hasLastValue && Equals(_lastValue, result.Value))
// Value dedup — but bypass it while recovering from Bad, so a recovery whose value equals the
// pre-failure value still republishes Good (otherwise the node would stay Bad forever).
if (!_lastPublishedBad && _hasLastValue && Equals(_lastValue, result.Value))
{
OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair<string, object?>("outcome", "skip"));
return;
@@ -143,11 +163,41 @@ public sealed class VirtualTagActor : ReceiveActor
_hasLastValue = true;
_lastValue = result.Value;
_lastPublishedBad = false;
OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair<string, object?>("outcome", "ok"));
var evalResult = new EvaluationResult(_virtualTagId, result.Value, msg.TimestampUtc, CorrelationId.NewId());
Context.Parent.Tell(evalResult);
}
/// <summary>02/S13 failure tail shared by the evaluator-threw catch and the <c>!Success</c> branch.
/// Always meters + publishes the per-failure script-log entry (the pre-existing operator
/// diagnostic); additionally publishes a Bad <see cref="EvaluationResult"/> — carrying the
/// last-known value if any — once per Good→Bad transition, and only after every declared dependency
/// has arrived (the inputs-ready gate that suppresses the cold-start/respawn warm-up flash).</summary>
/// <param name="reason">The failure reason for the script-log entry.</param>
/// <param name="level">The script-log level ("Warning" for a Failure result, "Error" for a throw).</param>
/// <param name="timestampUtc">The triggering dependency change's timestamp, stamped on the Bad result.</param>
private void OnEvaluationFailed(string reason, string level, DateTime timestampUtc)
{
OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair<string, object?>("outcome", "fail"));
PublishLog(level, reason);
if (_lastPublishedBad || !AllDependenciesArrived())
{
return;
}
_lastPublishedBad = true;
Context.Parent.Tell(new EvaluationResult(
_virtualTagId, _hasLastValue ? _lastValue : null, timestampUtc, CorrelationId.NewId(), OpcUaQuality.Bad));
}
/// <summary>Inputs-ready gate (mirrors the dormant <c>VirtualTagEngine.AreInputsReady</c>): true once
/// every declared dependency ref has been seen at least once. Called once per failure — the ref list
/// is small, so no caching. A vacuously-true empty ref list means a no-dependency script degrades on
/// its first failure.</summary>
private bool AllDependenciesArrived() => _dependencyRefs.All(_dependencies.ContainsKey);
private void PublishLog(string level, string message)
{
var entry = new ScriptLogEntry(
@@ -85,11 +85,24 @@ public sealed class VirtualTagHostActor : ReceiveActor
private void OnApply(ApplyVirtualTags msg)
{
// Apply-boundary compile-cache drop: each deploy generation may carry edited script sources, and
// the production evaluator roots one collectible AssemblyLoadContext per compiled expression. Drop
// them here (mirroring ScriptedAlarmEngine's per-generation clear) so stale ALCs are reclaimed
// instead of accreting across edits. No-op for evaluators without a cache (NullVirtualTagEvaluator).
(_evaluator as IScriptCacheOwner)?.ClearCompiledScripts();
// Apply-boundary compile-cache drop (gated — 02/P7): the production evaluator roots one
// collectible AssemblyLoadContext per compiled expression, so a changed script set must drop the
// stale ALCs. But clearing on EVERY apply forces a full recompilation even on a byte-identical
// redeploy (and each unnecessary clear is an unnecessary 02/S12 race window). Clear only when the
// deployed EXPRESSION set actually changed. The cache is keyed by source only, so a rename /
// FolderPath move / Historize toggle (which respawns the child but keeps the source) needs no
// recompile; set semantics also mean two vtags sharing one expression keep it alive while either
// remains. _planByVtag still holds the PREVIOUS generation here (it is rebuilt to the desired set
// at the end of this method); on the first apply after (re)start it is empty, so the sets differ
// and the clear fires (harmless — converges the singleton evaluator's cache to this generation).
// NOTE: this gate reduces clear FREQUENCY only; the S12 retry-once in RoslynVirtualTagEvaluator —
// not this gate — is the correctness fix for a clear racing an in-flight evaluation.
var newExpressions = msg.Plans.Select(p => p.Expression).ToHashSet(StringComparer.Ordinal);
var prevExpressions = _planByVtag.Values.Select(p => p.Expression).ToHashSet(StringComparer.Ordinal);
if (!newExpressions.SetEquals(prevExpressions))
{
(_evaluator as IScriptCacheOwner)?.ClearCompiledScripts();
}
var desired = new HashSet<string>(msg.Plans.Select(p => p.VirtualTagId), StringComparer.Ordinal);
@@ -176,16 +189,22 @@ public sealed class VirtualTagHostActor : ReceiveActor
return;
}
// 02/S13: the child now expresses quality — a Good fresh value or a Bad degradation (script
// failure/timeout) carrying the last-known value. Bridge result.Quality through verbatim; the
// sink maps it to StatusCodes.Good/Bad on the node so a broken script no longer freezes Good.
_publishActor.Tell(new OpcUaPublishActor.AttributeValueUpdate(
nodeId, result.Value, OpcUaQuality.Good, result.TimestampUtc));
nodeId, result.Value, result.Quality, result.TimestampUtc));
// Historize iff the plan opted in. Reuses _planByVtag (kept in lock-step with _children), so
// no parallel map. The historian path key is the SAME folder-scoped NodeId we just published
// to. For a computed value source == server, so both timestamps are the evaluation time.
// to. For a computed value source == server, so both timestamps are the evaluation time. Bad
// results record BadInternalError (0x80020000u) — the dormant VirtualTagEngine's Bad-snapshot
// status — so the historian trend can distinguish a degraded sample from a Good one.
if (_planByVtag.TryGetValue(result.VirtualTagId, out var plan) && plan.Historize)
{
var status = result.Quality == OpcUaQuality.Good ? 0u : 0x80020000u /* BadInternalError — dormant-engine parity */;
_history.Record(nodeId, new DataValueSnapshot(
result.Value, 0u /* StatusCodes.Good */, result.TimestampUtc, result.TimestampUtc));
result.Value, status, result.TimestampUtc, result.TimestampUtc));
}
}