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

fix(runtime): stash dedup + applying-wedge watchdog; cache-failure diagnostics

Browse Source
This commit is contained in:
Joseph Doherty
2026-08-15 17:43:15 -04:00
parent bfbdce32e4
commit 0dbbb5ac6b
3 changed files with 451 additions and 37 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/Server/ZB.MOM.WW.OtOpcUa.Runtime/Drivers/DriverHostActor.cs
+160 -11
View File
@@ -64,6 +64,24 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// <summary>Publishing interval handed to each driver's SubscribeBulk pass after an apply.</summary>
private static readonly TimeSpan SubscriptionPublishingInterval = TimeSpan.FromSeconds(1);
/// <summary>Timer key for the <see cref="Applying"/>-state wedge watchdog. Started by
/// <see cref="BeginFetchAndCacheApply"/>, cancelled by <see cref="BecomeSteady"/>.</summary>
private const string ApplyWedgeTimerKey = "apply-wedged";
/// <summary>
/// How long the host may sit in <see cref="Applying"/> before it says so.
/// </summary>
/// <remarks>
/// Five minutes ≈ 2× the worst configured artifact-fetch deadline, so an ordinary slow fetch
/// never trips it and a genuinely wedged one always does. It is not a timeout: nothing is
/// cancelled or failed, because the apply may still land and the coordinator's own apply
/// deadline is the authority on when a deployment is dead. The watchdog exists purely so a host
/// stuck in <see cref="Applying"/> is VISIBLE — the pre-stash forward-spin used to make that
/// unmissable (a flood of log lines), and taking the spin away accidentally took the only alarm
/// with it.
/// </remarks>
public static readonly TimeSpan DefaultApplyWedgeTimeout = TimeSpan.FromMinutes(5);
/// <summary>
/// Cache key used when an artifact carries no cluster scoping (single-cluster or unscoped
/// deployments). A literal rather than an empty string so the row is visibly deliberate when
@@ -162,6 +180,37 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// </remarks>
public IStash Stash { get; set; } = null!;
/// <summary>
/// The set of deployment ids currently sitting in <see cref="Stash"/>, so the
/// <see cref="Applying"/> state stashes each distinct deployment AT MOST ONCE. Cleared in
/// <see cref="BecomeSteady"/>, which is the same moment <see cref="IStash.UnstashAll"/> empties
/// the stash itself — a dispatch that is re-stashed by the NEXT apply re-adds itself naturally.
/// </summary>
/// <remarks>
/// <para>
/// <b>It bounds the stash by DISTINCT deployments.</b> A coordinator that re-dispatches on a
/// timer (or several coordinators racing) can emit the same deployment many times inside one
/// apply window; without this, every copy is stashed and every copy is re-delivered on the
/// way back to <see cref="Steady"/> — an unbounded queue of messages that will all
/// short-circuit as duplicates anyway.
/// </para>
/// <para>
/// <b>It also moots an Akka stash-equality question — which was raised in review as a
/// restart hazard and, MEASURED, is not one on the pinned version.</b> The string
/// <c>"Can't stash the same message {0} more than once"</c> (the
/// <c>IllegalActorStateException</c> that <c>AbstractStash.Stash()</c> is documented to
/// throw when an envelope equals the last one stashed) IS present verbatim in the shipped
/// <c>Akka.dll</c> 1.5.62. But a throwaway probe actor on this exact package — stashing one
/// message instance twice in a row, then two value-equal instances, both with and without an
/// explicit sender — accepted all four stashes and never threw. So the guard is not on this
/// path in 1.5.62, and the dedup set is NOT fixing a live crash. What it does is make the
/// question moot: since <see cref="DispatchDeployment"/> is a <c>sealed record</c> (value
/// equality), a future Akka that does enforce the check would restart this host in the
/// middle of a deployment, and nothing here would have to change to stay safe.
/// </para>
/// </remarks>
private readonly HashSet<DeploymentId> _deferredDispatches = new();
/// <summary>The single VirtualTag-host child that spawns/reconciles Equipment-namespace
/// VirtualTagActors and bridges their results onto the OPC UA publish actor. Spawned in
/// <see cref="PreStart"/> when an OPC UA publish actor is wired; receives
@@ -320,6 +369,10 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// </summary>
private readonly Func<CommonsNodeId, bool>? _sharesHistorizationScopeWithLocal;
/// <summary>This host's <see cref="Applying"/>-wedge watchdog delay (see
/// <see cref="DefaultApplyWedgeTimeout"/>).</summary>
private readonly TimeSpan _applyWedgeTimeout;
/// <summary>
/// Host of this node's LocalDb replication partner — the only node that holds a copy of this
/// node's alarm queue, and therefore the only node it may ever stand down in favour of.
@@ -431,6 +484,8 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// <param name="telemetryHub">Per-cluster mesh Phase 5: optional node-local live-telemetry hub each
/// Primary-gated native-alarm transition is also emitted into, and which is threaded into the spawned
/// VirtualTag + ScriptedAlarm hosts. Defaults to null (admin-only nodes / tests skip the emit).</param>
/// <param name="applyWedgeTimeout">How long the host may sit in <see cref="Applying"/> before the
/// wedge watchdog logs a Warning. Defaults to <see cref="DefaultApplyWedgeTimeout"/>.</param>
/// <returns>The Akka.NET <see cref="Akka.Actor.Props"/> used to spawn this actor.</returns>
public static Props Props(
IDbContextFactory<OtOpcUaConfigDbContext>? dbFactory,
@@ -458,7 +513,8 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
ITelemetryLocalHub? telemetryHub = null,
IDriverPrimaryRoleSource? primaryRoleSource = null,
IHistorizationRoleView? historizationRoleView = null,
Func<CommonsNodeId, bool>? sharesHistorizationScopeWithLocal = null) =>
Func<CommonsNodeId, bool>? sharesHistorizationScopeWithLocal = null,
TimeSpan? applyWedgeTimeout = null) =>
// WARNING: this forwarding list is POSITIONAL, and Props.Create compiles it into an
// expression tree. Six IActorRef? parameters and several interface-typed ones mean a
// mis-ordered argument is usually type-compatible and therefore compiles clean, then binds
@@ -470,7 +526,7 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
loggerFactory, scriptRootLogger, scriptedAlarmHostOverride, invokerFactory, driverMemberCountProvider,
deploymentArtifactCache, redundancyRoleView, replicationPeerHost, fetchAndCacheMode, artifactFetcher,
alarmStateStore, telemetryHub, primaryRoleSource, historizationRoleView,
sharesHistorizationScopeWithLocal));
sharesHistorizationScopeWithLocal, applyWedgeTimeout));
/// <summary>Initializes a new DriverHostActor with the specified dependencies.</summary>
/// <param name="dbFactory">Database context factory for configuration database access.</param>
@@ -526,6 +582,9 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// snapshot serves this node's address space and therefore records the same historized refs. Null
/// (the default) means the caller could not establish it, and this node never stands down — see
/// <see cref="PrimaryGatePolicy.ShouldRecordHistorizedValues"/>.</param>
/// <param name="applyWedgeTimeout">How long the host may sit in <see cref="Applying"/> before the
/// wedge watchdog logs a Warning. Defaults to <see cref="DefaultApplyWedgeTimeout"/>; a test shortens
/// it so the watchdog is observable in a test's lifetime.</param>
public DriverHostActor(
IDbContextFactory<OtOpcUaConfigDbContext>? dbFactory,
CommonsNodeId localNode,
@@ -552,8 +611,10 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
ITelemetryLocalHub? telemetryHub = null,
IDriverPrimaryRoleSource? primaryRoleSource = null,
IHistorizationRoleView? historizationRoleView = null,
Func<CommonsNodeId, bool>? sharesHistorizationScopeWithLocal = null)
Func<CommonsNodeId, bool>? sharesHistorizationScopeWithLocal = null,
TimeSpan? applyWedgeTimeout = null)
{
_applyWedgeTimeout = applyWedgeTimeout ?? DefaultApplyWedgeTimeout;
_historizationRoleView = historizationRoleView;
_sharesHistorizationScopeWithLocal = sharesHistorizationScopeWithLocal;
_telemetryHub = telemetryHub;
@@ -957,9 +1018,18 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// by grep. The constructor is the one exception: <see cref="Stash"/> is assigned by the
/// ActorCell only after construction returns.
/// </para>
/// <para>
/// It is also the single place the <see cref="Applying"/> state's two side-tables are
/// released: <see cref="_deferredDispatches"/> (which must be cleared in lockstep with the
/// unstash, or the re-delivered dispatch would be treated as an already-deferred duplicate
/// and dropped) and the <see cref="ApplyWedgeTimerKey"/> watchdog.
/// </para>
/// </remarks>
private void BecomeSteady()
{
// Cancelled BEFORE the unstash so a re-stash by the very next apply starts a fresh window.
Timers.Cancel(ApplyWedgeTimerKey);
_deferredDispatches.Clear();
Become(Steady);
Stash.UnstashAll();
}
@@ -969,6 +1039,8 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
Receive<DispatchDeployment>(HandleDispatchFromSteady);
Receive<ArtifactCached>(HandleArtifactCached);
Receive<ArtifactCacheFailed>(HandleArtifactCacheFailed);
// A wedge tick already in the mailbox when the apply finished — dropped at Debug, see the handler.
Receive<ApplyWedged>(HandleApplyWedged);
Receive<GetDiagnostics>(HandleGetDiagnostics);
Receive<DriverInstanceActor.AttributeValueBatchPublished>(ForwardBatchToMux);
Receive<DriverInstanceActor.AttributeAlarmPublished>(ForwardNativeAlarm);
@@ -997,6 +1069,16 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
return;
}
// At most ONE stashed copy per distinct deployment (see _deferredDispatches): the redundant
// copies would all short-circuit as duplicates on the way out anyway, so a re-dispatching
// coordinator would otherwise grow the stash with retries rather than with work.
if (!_deferredDispatches.Add(msg.DeploymentId))
{
_log.Debug("DriverHost {Node}: dispatch for {Id} is already deferred behind {Cur}; dropping the duplicate",
_localNode, msg.DeploymentId, _applyingDeploymentId);
return;
}
// Stashed, NOT re-forwarded to Self: a forward re-enqueues on this actor's own mailbox and
// is dequeued again immediately, spinning for the whole apply. Every transition back to
// Steady unstashes (see BecomeSteady), so this is logged once per deferred dispatch rather
@@ -1012,6 +1094,7 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
// its completion can land in EITHER state and both must handle it or it dead-letters.
Receive<ArtifactCached>(HandleArtifactCached);
Receive<ArtifactCacheFailed>(HandleArtifactCacheFailed);
Receive<ApplyWedged>(HandleApplyWedged);
Receive<GetDiagnostics>(HandleGetDiagnostics);
Receive<DriverInstanceActor.AttributeValueBatchPublished>(ForwardBatchToMux);
Receive<DriverInstanceActor.AttributeAlarmPublished>(ForwardNativeAlarm);
@@ -1573,6 +1656,13 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
{
_log.Warning("DriverHost {Node}: ignoring DispatchDeployment while Stale (DB unreachable)", _localNode);
});
// A cache store started before this node fell Stale still pipes back here (see
// CacheAppliedArtifact: Bootstrap's orphan-replay ApplyAndAck and RestoreApplied both start
// stores, and either can be followed by the ConfigDb failure that lands us in Stale). Without
// these the pipe-back dead-letters and a failed cache write goes unreported in exactly the
// situation — central unreachable — where the local cache is the thing keeping the node alive.
Receive<ArtifactCached>(HandleArtifactCached);
Receive<ArtifactCacheFailed>(HandleArtifactCacheFailed);
Receive<GetDiagnostics>(HandleGetDiagnostics);
Receive<RetryConfigDbConnection>(_ => TryRecoverFromStale());
Receive<RestartDriver>(HandleRestartDriver);
@@ -1649,10 +1739,19 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// inside a receive. The apply itself completes synchronously on the actor thread in
/// <see cref="HandleFetchedForApply"/>, mirroring <see cref="ApplyAndAck"/>.
/// </summary>
/// <remarks>
/// This is the ONLY path that arms the <see cref="ApplyWedgeTimerKey"/> watchdog, deliberately.
/// <see cref="ApplyAndAck"/> enters and leaves <see cref="Applying"/> inside a single mailbox
/// turn, so it cannot be "stuck in Applying" in any sense a watchdog could report: if it hung,
/// it would be hanging the actor thread, and a watchdog delivered as a mailbox message could not
/// be dequeued to say so. The fetch is the only unbounded wait during which the host is still
/// alive and dequeuing — which is exactly what makes a silent wedge possible there.
/// </remarks>
private void BeginFetchAndCacheApply(DeploymentId deploymentId, RevisionHash revision, CorrelationId correlation)
{
_applyingDeploymentId = deploymentId;
Become(Applying);
Timers.StartSingleTimer(ApplyWedgeTimerKey, new ApplyWedged(deploymentId), _applyWedgeTimeout);
// Persist Applying row (idempotent on PK) — same crash-boundary marker as ApplyAndAck.
UpsertNodeDeploymentState(deploymentId, NodeDeploymentStatus.Applying, failureReason: null);
@@ -1762,6 +1861,39 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
}
}
/// <summary>
/// Self-timer telling this host it has been in <see cref="Applying"/> for
/// <see cref="_applyWedgeTimeout"/> without finishing.
/// </summary>
private sealed record ApplyWedged(DeploymentId DeploymentId);
/// <summary>
/// Reports a host that is still in <see cref="Applying"/> long after it should have finished.
/// </summary>
/// <remarks>
/// Purely a signal — nothing is cancelled and no ACK is sent, because the apply may yet land and
/// the coordinator's apply deadline already owns "this deployment is dead". Registered in
/// <see cref="Applying"/> AND <see cref="Steady"/>: <see cref="BecomeSteady"/> cancels the timer,
/// but a fire already in the mailbox when the apply completes still has to land somewhere, and
/// dead-lettering it would be a second, more confusing signal. Such a late fire finds
/// <see cref="_applyingDeploymentId"/> null (or naming a different deployment) and drops at Debug.
/// </remarks>
private void HandleApplyWedged(ApplyWedged msg)
{
if (_applyingDeploymentId is null || msg.DeploymentId != _applyingDeploymentId.Value)
{
_log.Debug("DriverHost {Node}: late apply-wedge tick for {Id} (in-flight={Cur}); dropping",
_localNode, msg.DeploymentId, _applyingDeploymentId);
return;
}
_log.Warning(
"DriverHost {Node}: deployment {Id} appears WEDGED — still applying after {Timeout} " +
"(the artifact fetch has neither answered nor failed); {Deferred} further dispatch(es) are " +
"deferred behind it. The node keeps serving revision {Rev}.",
_localNode, msg.DeploymentId, _applyWedgeTimeout, _deferredDispatches.Count, _currentRevision);
}
/// <summary>Pipe-back carrier for a <c>FetchAndCache</c> fetch result (null bytes = no answer).</summary>
private sealed record FetchedForApply(
DeploymentId DeploymentId, RevisionHash Revision, CorrelationId Correlation, byte[]? Bytes);
@@ -2065,9 +2197,18 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
/// driver value burst, a diagnostics request or the next dispatch. The task is piped back as
/// <see cref="ArtifactCached"/>/<see cref="ArtifactCacheFailed"/> so completion is observed
/// rather than fire-and-forgotten — the earlier objection to this shape was that the
/// pipe-back needs a handler in every state it can land in, which is exactly why both
/// <see cref="Steady"/> and <see cref="Applying"/> register one. (<c>Stale</c> does not: it
/// is only ever entered from <see cref="Bootstrap"/>, before any apply has started a store.)
/// pipe-back needs a handler in every state it can land in, which is why
/// <see cref="Steady"/>, <see cref="Applying"/> AND <see cref="Stale"/> all register one.
/// </para>
/// <para>
/// <b>Stale is included on purpose.</b> This used to claim Stale could not be reached after a
/// store had started, because it is only ever entered from <see cref="Bootstrap"/>. That is
/// not a property of the Stale entry — <see cref="Bootstrap"/> starts stores of its own, via
/// the orphan-replay <see cref="ApplyAndAck"/> and via <see cref="RestoreApplied"/>, and both
/// run inside the very try block whose catch Becomes Stale. Today no statement between those
/// calls and the catch happens to throw, so the old claim held by accident of ordering rather
/// than by design; a restart can orphan an in-flight pipe-back the same way. Registering the
/// handlers costs two lines and removes the need to re-derive that argument.
/// </para>
/// <para>
/// <b>The apply does not depend on the outcome</b> — it never did, and the async shape keeps
@@ -2132,14 +2273,14 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
.PipeTo(
Self,
success: () => new ArtifactCached(deploymentId),
failure: ex => new ArtifactCacheFailed(deploymentId, ex.Message));
failure: ex => new ArtifactCacheFailed(deploymentId, ex));
}
catch (Exception ex)
{
// A cache that throws SYNCHRONOUSLY (before returning a task) never produces a pipe-back,
// so route it to the same handler by hand rather than letting it unwind into the apply's
// catch — which would send a second, contradictory Failed ACK for a live deployment.
Self.Tell(new ArtifactCacheFailed(deploymentId, ex.Message));
Self.Tell(new ArtifactCacheFailed(deploymentId, ex));
}
}
@@ -2152,17 +2293,25 @@ public sealed class DriverHostActor : ReceiveActor, IWithTimers, IWithUnboundedS
private sealed record ArtifactCached(DeploymentId DeploymentId);
/// <summary>The node-local artifact cache could not store this deployment's bytes.</summary>
private sealed record ArtifactCacheFailed(DeploymentId DeploymentId, string Reason);
/// <remarks>
/// Carries the <b>exception</b>, not a pre-flattened message string. A LocalDb/SQLite failure is
/// routinely a wrapped inner exception, and <c>ex.Message</c> alone ("An error occurred while
/// …") names neither the SQLite result code nor the frame that produced it — the detail an
/// operator needs to tell a full disk from a locked file from a schema mismatch. Logging it as
/// the log event's <c>Cause</c> also lets a test assert on the exception TYPE rather than on
/// prose.
/// </remarks>
private sealed record ArtifactCacheFailed(DeploymentId DeploymentId, Exception Cause);
private void HandleArtifactCached(ArtifactCached msg) =>
_log.Info("DriverHost {Node}: cached applied deployment {Id} as this node's local fallback",
_localNode, msg.DeploymentId);
private void HandleArtifactCacheFailed(ArtifactCacheFailed msg) =>
_log.Warning(
_log.Warning(msg.Cause,
"DriverHost {Node}: deployment {Id} could not be cached locally ({Reason}). The apply itself " +
"succeeded and is unaffected; this node simply has no local fallback for that revision.",
_localNode, msg.DeploymentId, msg.Reason);
_localNode, msg.DeploymentId, msg.Cause.Message);
/// <summary>
/// Restore the served state for an already-applied deployment after a process restart.