dohertj2/lmxopcua
1
0
Fork 0
Code Issues 5 Pull Requests Actions 1 Packages Projects Releases Wiki Activity

fix(opcua): deferred condition events never outlive their condition; per-condition bounded deferral; canonical lockout identity (#838, #844 review)

Browse Source 
#838 review of 91e28e87:
1. Ghost events. The deferred report ran the SDK walk off Lock with no
   liveness check, so an event waiting behind a full channel when a deploy
   removed its condition still reached i=2253 subscribers after the NodeDeleted
   (a ghost Retain alarm for ScadaBridge) and folder items. Delivery now walks
   the SDK path itself (OnReportEvent, OnReportEventAsync, inverse notifiers,
   then the Parent as BaseInstanceState does) re-checking before EVERY hop that
   the condition is the live instance; OnConditionReportEvent checks the same,
   which also stops a non-live scripted condition being admitted through its
   old equipment folder (#808). A guard test pins that only NodeState and
   BaseInstanceState define the walk. New wire test removes the condition in
   the same Lock hold as a flood; the flag-off variant fails without the checks.
2. Back-pressure. Deferral is per condition (one condition's events stay
   ordered; others are not held up). Overflow policy: coalesce, newest wins --
   past 1024 waiting per condition or 65,536 total, the oldest not-yet-started
   event is discarded (a condition event carries full state). Warning on
   entering deferral (<=1/min), Information on draining, meters
   otopcua.opcua.condition_events.deferred / .discarded{reason}.
3. Verified by decompiling SDK 2.0.1: the notifier list is snapshotted under the
   node's own lock, MonitoredNode2.Dispose completes its writer (pending writes
   fail with ChannelClosedException, swallowed), and the consumer catches
   per-event exceptions -- no fix needed; documented.
4. ConditionRefresh does not flush deferrals; documented as a residual.

#844 review: DescribeCredential canonicalises the key id (trim, lowercase;
non-hex ids fold into one identity) and the username, since ConfigDbApiKeyStore
matches with SQL Server's case-insensitive, trailing-space-blind `=`.
This commit is contained in:
Joseph Doherty
2026-11-11 04:35:30 -05:00
parent fc3a39b1ca
commit 7482a88888
8 changed files with 428 additions and 64 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/Core/ZB.MOM.WW.OtOpcUa.Commons/Observability/OtOpcUaTelemetry.cs
+18
View File
@@ -154,6 +154,24 @@ public static class OtOpcUaTelemetry
Meter.CreateCounter<long>("otopcua.opcua.apikey_store.bounded", unit: "{lookup}",
description: "API-key store lookups the bound intervened on (outcome=timeout|cache_hit).");
/// <summary>
/// Part 9 condition events whose delivery is currently deferred because an event notifier's SDK delivery
/// channel was full (Gitea #838). Zero in steady state; non-zero means some folder's event subscribers are
/// not keeping up with the alarm event rate (or the node manager lock is held across a large burst).
/// </summary>
public static readonly UpDownCounter<long> ConditionEventReportsDeferred =
Meter.CreateUpDownCounter<long>("otopcua.opcua.condition_events.deferred", unit: "{event}",
description: "Condition events waiting for room in an event notifier's delivery channel.");
/// <summary>
/// Deferred condition events discarded before delivery (Gitea #838): <c>reason=coalesced</c> — the per-condition
/// deferral budget was exceeded and the condition's oldest not-yet-started event gave way to its newest;
/// <c>reason=not_live</c> — the condition was removed or replaced before its deferred event was delivered.
/// </summary>
public static readonly Counter<long> ConditionEventReportsDiscarded =
Meter.CreateCounter<long>("otopcua.opcua.condition_events.discarded", unit: "{event}",
description: "Deferred condition events discarded before delivery (reason=coalesced|not_live).");
// ---------------- Convenience helpers ----------------
/// <summary>
src/Server/ZB.MOM.WW.OtOpcUa.Host/OpcUa/ApiKeyOpcUaUserAuthenticator.cs
+17 -2
View File
@@ -168,8 +168,23 @@ public sealed class ApiKeyOpcUaUserAuthenticator : IOpcUaUserAuthenticator
// lmxopcua#844 — the key id is public (it is the lookup index, never the secret), so guesses at different keys
// are counted apart and a client's own successful key cannot clear the count of a key it is guessing at.
// A credential that is not a well-formed key falls back to the username (all such guesses share one count).
public string DescribeCredential(string username, string password) =>
ApiKeySecret.TryParse(password, out var apiKeyId, out _) ? "key:" + apiKeyId : "user:" + username;
//
// #844 review: the identity is CANONICAL, never the raw presented id. ConfigDbApiKeyStore matches the id with SQL
// Server `=` under a case-insensitive collation that also ignores trailing spaces, so `otua_abc…`, `otua_ABC…` and
// `otua_abc… ` reach the same key row — as separate lockout identities they would each get a fresh per-credential
// count. Minted ids are lowercase hex (ApiKeySecret.Generate), so: trim, lowercase, and fold every id outside that
// charset (which no real key can carry) into one shared identity. The username is folded the same way. Merging
// only ever makes the per-credential count stricter; the per-client cap is unaffected.
public string DescribeCredential(string username, string password)
{
if (!ApiKeySecret.TryParse(password, out var apiKeyId, out _))
return "user:" + (username ?? string.Empty).Trim().ToLowerInvariant();
var canonical = apiKeyId.Trim().ToLowerInvariant();
return canonical.Length > 0 && canonical.All(char.IsAsciiHexDigitLower)
? "key:" + canonical
: "key:<not-a-minted-id>";
}
/// <inheritdoc />
// Resolves the <c>anonymous</c> principal's grants through the same mapper a key's principal
src/Server/ZB.MOM.WW.OtOpcUa.OpcUaServer/OtOpcUaNodeManager.cs
+222 -52
View File
@@ -4,6 +4,7 @@ using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Opc.Ua;
using Opc.Ua.Server;
using ZB.MOM.WW.OtOpcUa.Commons.Observability;
using ZB.MOM.WW.OtOpcUa.Commons.OpcUa;
using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
using ZB.MOM.WW.OtOpcUa.Core.Authorization;
@@ -1400,22 +1401,44 @@ public sealed class OtOpcUaNodeManager : CustomNodeManager2, INodeManager3
}
}
/// <summary>Serializes <see cref="_eventReportChain"/>.</summary>
private readonly object _eventReportGate = new();
/// <summary>The tail of the deferred condition-event reports (Gitea #838); completed when none is pending.</summary>
private Task _eventReportChain = Task.CompletedTask;
private int _deferredEventReports;
/// <summary>Condition-event reports currently deferred because a notifier's delivery channel was full (test observation).</summary>
internal int DeferredEventReports => Volatile.Read(ref _deferredEventReports);
/// <summary>The most deferred events one condition may hold before its oldest not-yet-started one gives way (#838).</summary>
internal const int MaxDeferredEventsPerCondition = 1024;
/// <summary>
/// Reports a condition event through the condition's notifier chain WITHOUT blocking the caller, in report
/// order (Gitea #838).
/// The total deferred events across all conditions beyond which each new deferral coalesces its condition's
/// queue down to its newest event (#838). Each condition always keeps its newest, so the true ceiling is this
/// plus the number of conditions.
/// </summary>
/// <param name="source">The condition.</param>
internal const int MaxDeferredEventsTotal = 65_536;
private static readonly TimeSpan DeferralWarningInterval = TimeSpan.FromMinutes(1);
/// <summary>Guards <see cref="_deferredReports"/> and the deferral episode bookkeeping. Never held across a delivery.</summary>
private readonly object _eventReportGate = new();
/// <summary>Conditions with deferred events, each with its own ordered queue (#838). Keyed by instance.</summary>
private readonly Dictionary<AlarmConditionState, DeferredConditionReports> _deferredReports =
new(System.Collections.Generic.ReferenceEqualityComparer.Instance);
private int _deferredEventReports;
private long _discardedEventReports;
private DateTime _lastDeferralWarningUtc = DateTime.MinValue;
private bool _episodeWarned;
private long _episodeDeferred;
private long _episodeDiscarded;
/// <summary>Condition events currently deferred — queued or in flight (test observation).</summary>
internal int DeferredEventReports => Volatile.Read(ref _deferredEventReports);
/// <summary>Deferred condition events discarded before delivery, any reason (test observation).</summary>
internal long DiscardedEventReports => Interlocked.Read(ref _discardedEventReports);
/// <summary>
/// Reports a condition event through the condition's notifier chain WITHOUT blocking the caller, in the order
/// this condition's events were reported, and never for a condition that is no longer live (Gitea #838).
/// </summary>
/// <param name="condition">The condition (must be the live instance — every caller holds <c>Lock</c>).</param>
/// <param name="e">The frozen snapshot of the event.</param>
/// <remarks>
/// <para>
@@ -1423,72 +1446,212 @@ public sealed class OtOpcUaNodeManager : CustomNodeManager2, INodeManager3
/// <c>MonitoredNode2</c> whose delivery task drains a BOUNDED channel (4096, <c>FullMode = Wait</c>), and
/// the synchronous <c>ReportEvent</c> BLOCKS when that channel is full. Condition events are reported
/// under <c>Lock</c>, and the delivery task takes <c>Lock</c> on every per-event verdict-cache miss (the
/// SDK's own <c>GetNodeMetadata</c>, and #826's <see cref="IsNotifierEventVisibleTo"/>). So a burst of more
/// than 4096 events under one hold of <c>Lock</c>, starting at a miss, parked the consumer on <c>Lock</c>
/// while the producer waited on the consumer: a deadlock that froze the whole node manager (pinned by
/// <c>FolderEventFloodWireTests</c>, which stalled at exactly 4097 events before this).
/// SDK's own <c>GetNodeMetadata</c> — flag off too — and #826's <see cref="IsNotifierEventVisibleTo"/>). So
/// a burst of more than 4096 events under one hold of <c>Lock</c>, starting at a miss, deadlocked the
/// node manager (<c>FolderEventFloodWireTests</c> stalled at exactly 4097 events before this).
/// </para>
/// <para>
/// <b>What this does.</b> The common case is unchanged and synchronous: <c>ReportEventAsync</c> completes
/// inline while every channel has room. Only when a channel is full does that report continue
/// asynchronously (awaiting channel space, holding no thread and no lock), and every later report queues
/// behind it, so events still leave in the order they were reported. The deferred work holds only frozen
/// snapshots, so it is bounded by the burst that caused it and drains once <c>Lock</c> is released.
/// Delivery to clients stays bounded by each monitored item's own queue (oldest discarded). A deferred
/// report runs the condition's synchronous <c>OnReportEvent</c> hook (<see cref="OnConditionReportEvent"/>)
/// off <c>Lock</c>; that hook takes <c>Lock</c> itself where it reads guarded state.
/// <b>Delivery.</b> <see cref="DeliverConditionEventAsync"/> walks the same path the SDK's
/// <c>ReportEventAsync</c> does (the node's sync <c>OnReportEvent</c>, its <c>MonitoredNode2</c>, then each
/// inverse notifier recursively, from a snapshot of the notifier list) — but re-checks before EVERY hop that
/// the condition is still the live instance, so an event deferred past a deploy that removed or replaced
/// it is dropped rather than delivered as a ghost (review of 91e28e87). The common case is unchanged and
/// synchronous: the walk completes inline while every channel has room.
/// </para>
/// <para>
/// <b>Deferral.</b> When a channel is full the walk continues asynchronously (holding no thread or lock),
/// and the condition gets a queue: its later events wait behind it, so ONE condition's events stay in
/// order, while other conditions whose channels have room are not held up (per-condition, not global).
/// Events of different conditions may interleave differently than reported — each carries its own
/// condition's full state, so nothing a client derives depends on cross-condition order.
/// </para>
/// <para>
/// <b>Overflow policy: coalesce, newest wins.</b> A condition holds at most
/// <see cref="MaxDeferredEventsPerCondition"/> waiting events; past that, or while the total exceeds
/// <see cref="MaxDeferredEventsTotal"/>, its OLDEST not-yet-started event is discarded and counted
/// (<c>otopcua.opcua.condition_events.discarded{reason=coalesced}</c>). A condition event carries the
/// condition's complete state, so the newest supersedes the older ones for every Retain-based consumer
/// (ScadaBridge); what is lost is intermediate transitions on the OPC UA event stream only, never the
/// final state (alarm history is recorded by the engine/driver path, not from these events). Dropping
/// the newest instead would leave subscribers on a stale state; blocking is the deadlock above.
/// </para>
/// <para>
/// <b>Visibility.</b> Entering deferral logs a Warning (at most once a minute), leaving it an Information
/// line with the episode's counts; <c>otopcua.opcua.condition_events.deferred</c> is the live depth.
/// </para>
/// </remarks>
private void ReportEventWithoutBlocking(NodeState source, IFilterTarget e)
private void ReportEventWithoutBlocking(AlarmConditionState condition, IFilterTarget e)
{
lock (_eventReportGate)
{
if (_eventReportChain.IsCompleted)
if (_deferredReports.TryGetValue(condition, out var queued))
{
var report = source.ReportEventAsync(SystemContext, e);
if (report.IsCompletedSuccessfully) return;
Interlocked.Increment(ref _deferredEventReports);
_eventReportChain = ObserveEventReportAsync(report.AsTask(), source);
EnqueueDeferred(condition, queued, e);
return;
}
Interlocked.Increment(ref _deferredEventReports);
_eventReportChain = ReportAfterAsync(_eventReportChain, source, e);
}
}
private async Task ReportAfterAsync(Task previous, NodeState source, IFilterTarget e)
{
await previous.ConfigureAwait(false); // never faults: every link observes its own failure
Task report;
// Every caller holds Lock, so no other report of this condition can start until this returns; the gate is
// NOT held across the delivery (the delivery may take Lock, and gate→Lock against Lock→gate would deadlock).
ValueTask delivery;
try
{
report = source.ReportEventAsync(SystemContext, e).AsTask();
delivery = DeliverConditionEventAsync(condition, condition, e);
}
catch (Exception ex)
{
report = Task.FromException(ex);
delivery = ValueTask.FromException(ex);
}
await ObserveEventReportAsync(report, source).ConfigureAwait(false);
if (delivery.IsCompletedSuccessfully) return;
lock (_eventReportGate)
{
var queue = new DeferredConditionReports();
_deferredReports[condition] = queue;
CountDeferred(+1, condition);
_ = DrainDeferredAsync(condition, queue, delivery.AsTask());
}
}
private async Task ObserveEventReportAsync(Task report, NodeState source)
/// <summary>Queues a later event behind a condition's deferred one, coalescing past the budget. Under the gate.</summary>
private void EnqueueDeferred(AlarmConditionState condition, DeferredConditionReports queue, IFilterTarget e)
{
try
queue.Pending.Enqueue(e);
CountDeferred(+1, condition);
while (queue.Pending.Count > 1
&& (queue.Pending.Count > MaxDeferredEventsPerCondition || _deferredEventReports > MaxDeferredEventsTotal))
{
await report.ConfigureAwait(false);
}
catch (Exception ex)
{
_logger.LogError(ex, "OtOpcUaNodeManager: failed to report Part 9 condition event for {NodeId}", source.NodeId);
}
finally
{
Interlocked.Decrement(ref _deferredEventReports);
queue.Pending.Dequeue();
CountDeferred(-1, condition);
CountDiscarded("coalesced");
}
}
/// <summary>Delivers a condition's deferred events in order, one at a time, then forgets the queue.</summary>
private async Task DrainDeferredAsync(AlarmConditionState condition, DeferredConditionReports queue, Task inFlight)
{
var current = inFlight;
while (true)
{
try
{
await current.ConfigureAwait(false);
}
catch (Exception ex)
{
_logger.LogError(ex, "OtOpcUaNodeManager: failed to report Part 9 condition event for {NodeId}", condition.NodeId);
}
IFilterTarget next;
lock (_eventReportGate)
{
CountDeferred(-1, condition);
if (queue.Pending.Count == 0)
{
_deferredReports.Remove(condition);
return;
}
next = queue.Pending.Dequeue();
}
try
{
current = DeliverConditionEventAsync(condition, condition, next).AsTask();
}
catch (Exception ex)
{
current = Task.FromException(ex);
}
}
}
/// <summary>
/// The SDK's <c>NodeState.ReportEventAsync</c> walk — the node's sync <c>OnReportEvent</c>, its async
/// <c>OnReportEventAsync</c> (a <c>MonitoredNode2</c>), then each inverse notifier recursively from a snapshot of
/// the notifier list, then (<c>BaseInstanceState</c>) the Parent — with a liveness check before every hop (#838
/// review). A guard test pins that the SDK still has no other override. <c>EventReported</c> is not
/// raised: nothing in the SDK or this repo subscribes to it, and it cannot be raised from outside the node.
/// </summary>
private async ValueTask DeliverConditionEventAsync(AlarmConditionState condition, NodeState node, IFilterTarget e)
{
if (!IsLiveCondition(condition))
{
// Removed or replaced while this event waited. Counted once, at the event's first hop.
if (ReferenceEquals(node, condition)) CountDiscarded("not_live");
return;
}
node.OnReportEvent?.Invoke(SystemContext, node, e);
if (node.OnReportEventAsync is { } handler)
await handler(SystemContext, node, e, CancellationToken.None).ConfigureAwait(false);
var notifiers = new List<NodeState.Notifier>();
node.GetNotifiers(SystemContext, notifiers);
foreach (var notifier in notifiers)
{
if (notifier.IsInverse && notifier.Node is { } next)
await DeliverConditionEventAsync(condition, next, e).ConfigureAwait(false);
}
// BaseInstanceState.ReportEventAsync (the only override in SDK 2.0.1 — decompiled Types/Server/Core) runs the
// base walk above and THEN reports to its Parent: that is how a condition's events reach the folder it hangs under.
if (node is BaseInstanceState { Parent: { } parent })
await DeliverConditionEventAsync(condition, parent, e).ConfigureAwait(false);
}
/// <summary>Whether <paramref name="condition"/> is the instance the address space currently holds for its NodeId.</summary>
private bool IsLiveCondition(NodeState condition) =>
_alarmConditions.TryGetValue(MapKey(condition.NodeId), out var live) && ReferenceEquals(live, condition);
/// <summary>Adjusts the deferred depth and logs episode entry/exit. Under the gate.</summary>
private void CountDeferred(int delta, AlarmConditionState condition)
{
var before = _deferredEventReports;
_deferredEventReports += delta;
OtOpcUaTelemetry.ConditionEventReportsDeferred.Add(delta);
if (delta > 0) _episodeDeferred += delta;
if (before == 0 && delta > 0)
{
_episodeDeferred = delta;
_episodeDiscarded = 0;
var now = DateTime.UtcNow;
_episodeWarned = now - _lastDeferralWarningUtc >= DeferralWarningInterval;
if (_episodeWarned)
{
_lastDeferralWarningUtc = now;
_logger.LogWarning(
"OtOpcUaNodeManager: condition events are being deferred — an event notifier's delivery channel is "
+ "full (first: {NodeId}). Folder event subscribers are not keeping up, or Lock is held across a large "
+ "burst; events stay ordered per condition, and past {PerCondition} waiting per condition the oldest "
+ "give way to the newest (Gitea #838)",
condition.NodeId, MaxDeferredEventsPerCondition);
}
}
else if (_deferredEventReports == 0 && before > 0 && _episodeWarned)
{
_logger.LogInformation(
"OtOpcUaNodeManager: deferred condition events drained ({Deferred} deferred, {Discarded} discarded this episode)",
_episodeDeferred, _episodeDiscarded);
}
}
private void CountDiscarded(string reason)
{
Interlocked.Increment(ref _discardedEventReports);
lock (_eventReportGate) _episodeDiscarded++;
OtOpcUaTelemetry.ConditionEventReportsDiscarded.Add(1, new KeyValuePair<string, object?>("reason", reason));
}
/// <summary>One condition's deferred events: the one in flight is held by the drain loop, the rest wait here.</summary>
private sealed class DeferredConditionReports
{
public readonly Queue<IFilterTarget> Pending = new();
}
/// <summary>
/// The gate-relevant slice of a Part 9 condition's state — exactly the fields that drive a
/// condition event AND that an <see cref="AlarmConditionSnapshot"/> can change. As a record, two
@@ -5316,6 +5479,13 @@ public sealed class OtOpcUaNodeManager : CustomNodeManager2, INodeManager3
{
if (_allEventsItems.IsEmpty) return;
// #838 review: never for a condition a deploy has removed or replaced. The hook stays attached to a torn-down
// instance, and an event reported off Lock (a deferred report, an SDK method audit racing a teardown) would
// otherwise hand Server-object subscribers a ghost Retain alarm after its NodeDeleted — and, with the ACL on,
// a non-live scripted condition skips ConditionVisibilityScopes' "condition alone" rule and could be admitted
// through its OLD equipment folder (#808).
if (!IsLiveCondition(node)) return;
var scopes = AclEnforced ? ConditionVisibilityScopes(node) : null;
var reportingSession = (context as ISessionSystemContext)?.SessionId;