fix(mesh): PreStart resolve race logs honestly — quiet on heal, loud on permanent absence

PreStart's eager resolve of IMeshCommandDialer/IMeshPskProvider loses a
millisecond-wide race against the Akka builder's remaining starters on
essentially every admin boot (live gates: 1A 2/3 boots, 1B 4/4 boots) and
self-heals at the memoized Dialer/PskProvider properties' first use. Before
this change that produced two FALSE Errors per healthy boot, which made a
soak error-grep on a healthy rig impossible.

Resolve() now takes a `firstUse` flag and logs at Debug on BOTH call sites
(PreStart and the memoized properties' retry) — from inside Resolve a lost
race and a genuinely broken factory are indistinguishable, so severity is
decided by the CONSUMER of a still-null result after the retry, not by
Resolve itself:

  - Dialer: DispatchOverGrpc's existing per-dispatch Error ("no command
    dialer is wired") is unchanged and is now the ONLY loud signal for that
    dependency.
  - PskProvider: PublishKnownClusters gained a new Error carrying the old
    PreStart guard's diagnostic content (gate never published, cached keys
    never dropped, rotated key needs restart), guarded to fire ONCE per
    actor incarnation via `_pskProviderAbsenceReported` — that handler runs
    on the contact-refresh timer for the actor's whole life, so an
    unguarded Error there would repeat every ContactRefreshSeconds forever.

Design choice for the "factory never supplied" case (Dps/ClusterClient test
constructions that pass no factories at all): kept silent at BOTH call
sites for both dependencies, same as before. For the dialer this was
already true (DispatchOverGrpc's check doesn't care why the dialer is
null). For the PSK provider the new once-guarded Error is gated on
`_pskProviderFactory is not null` specifically so the many existing
ClusterClient/Dps facts in CentralCommunicationActorTests that never wire a
PSK provider (using the bare Spawn helper) keep passing unmodified — a
never-supplied factory is a deliberate wiring/test choice, not a resolve
failure, and Resolve() already stayed silent about it for the same reason.

Two new tests pin the net behavior: a healthy boot (factories that throw
once then succeed) produces zero Warning/Error end-to-end through PreStart,
the first contact load and the first dispatch; a permanently-broken PSK
provider logs the absence exactly once across two contact loads, not once
per refresh.

Claude-Session: https://claude.ai/code/session_014WNM4vjoVksyyBraTXSZE1

src/Server/ZB.MOM.WW.OtOpcUa.ControlPlane/Communication/CentralCommunicationActor.cs

@@ -81,9 +81,11 @@ public sealed class CentralCommunicationActor : ReceiveActor, IWithTimers
     // long after every starter finished, so a lost boot race self-heals there. Actor-thread
     // only, so ??= needs no synchronisation; both are container singletons, so a repeat resolve
     // is a dictionary hit.
-    private IMeshPskProvider? PskProvider => _pskProvider ??= Resolve(_pskProviderFactory, nameof(IMeshPskProvider));
+    private IMeshPskProvider? PskProvider =>
+        _pskProvider ??= Resolve(_pskProviderFactory, nameof(IMeshPskProvider), firstUse: true);
 
-    private IMeshCommandDialer? Dialer => _dialer ??= Resolve(_dialerFactory, nameof(IMeshCommandDialer));
+    private IMeshCommandDialer? Dialer =>
+        _dialer ??= Resolve(_dialerFactory, nameof(IMeshCommandDialer), firstUse: true);
 
     private readonly ILoggingAdapter _log = Context.GetLogger();
     private readonly bool _useClusterClient;
@@ -100,6 +102,14 @@ public sealed class CentralCommunicationActor : ReceiveActor, IWithTimers
     // thread only.
     private readonly HashSet<string> _warnedPortlessNodes = new(StringComparer.Ordinal);
 
+    // Set once PublishKnownClusters has reported a genuinely-absent PSK provider (a factory WAS
+    // supplied and still resolves null after the first-use retry). PublishKnownClusters runs on
+    // the contact-refresh timer forever, so without this an actor with a permanently broken
+    // provider would repeat the Error every ContactRefreshSeconds for its whole life — the same
+    // per-refresh noise this fix removes, just relocated. Same warn-once shape as
+    // _warnedPortlessNodes; actor thread only.
+    private bool _pskProviderAbsenceReported;
+
     // The gRPC dispatch set, replaced wholesale on every contact load. Actor thread only; the fan
     // captures the list reference, so a refresh mid-fan cannot mutate a dispatch already under way.
     private IReadOnlyList<MeshNodeTarget> _targets = [];
@@ -226,8 +236,16 @@ public sealed class CentralCommunicationActor : ReceiveActor, IWithTimers
         // First point at which the host is fully built — see the Props remark. Re-runs on every
         // actor restart, which re-reads the container rather than caching a stale reference; both
         // dependencies are container singletons, so a restart gets the same instances back.
-        _dialer = Resolve(_dialerFactory, nameof(IMeshCommandDialer));
+        //
-        _pskProvider = Resolve(_pskProviderFactory, nameof(IMeshPskProvider));
+        // Quiet (firstUse: false — see Resolve): PreStart runs on a dispatcher thread concurrently
+        // with the builder's remaining starters and loses a millisecond-wide race against
+        // AuditWriterActorKey's registration (starter #4) on essentially every admin boot (live
+        // gates: 1A 2/3 boots, 1B 4/4 boots). That is the ORDINARY case, not a malfunction — the
+        // memoized PskProvider/Dialer properties retry on first use, long after every starter
+        // finished, and the lost race self-heals there almost every time. Logging it as
+        // Warning/Error twice a boot is what made a soak error-grep on a healthy rig impossible.
+        _dialer = Resolve(_dialerFactory, nameof(IMeshCommandDialer), firstUse: false);
+        _pskProvider = Resolve(_pskProviderFactory, nameof(IMeshPskProvider), firstUse: false);
 
         if (!_useClusterClient && !_useGrpc)
         {
@@ -238,28 +256,15 @@ public sealed class CentralCommunicationActor : ReceiveActor, IWithTimers
                 + "which is mapped by port and does not care about this mode", _options.Mode);
         }
 
-        if (_useGrpc && _dialer is null)
+        // Deliberately NO null guard for either dependency here. At this point a still-null value
-        {
+        // is indistinguishable from the starter-ordering race Resolve just logged quietly above —
-            // Not a fatal throw: the ack path (HandleApplyAck) is transport-independent and still
+        // reporting it loudly here would be the exact false alarm this fix removes, on nearly
-            // works, so taking the actor down would turn a command-plane mis-wiring into an ack
+        // every boot. A retry that ALSO fails — the genuinely permanent absence — is reported
-            // outage as well. Every dispatch logs its own error, so this cannot go unnoticed.
+        // loudly where it actually costs something instead: DispatchOverGrpc for the dialer (every
-            _log.Error(
+        // dropped command, unchanged — see the EventFilter pin on that message), and
-                "Mesh transport is Grpc but no command dialer was supplied to this actor; EVERY "
+        // PublishKnownClusters for the PSK provider (once per incarnation, not once per refresh
-                + "central→node command will be dropped. Check the ControlPlane registration wires "
+        // forever, since that handler runs on the contact-refresh timer for the actor's whole
-                + "IMeshCommandDialer");
+        // life).
-        }
-
-        if (_pskProvider is null)
-        {
-            // Mode-independent, like the gate itself. A silent absence here is the worst of the
-            // three outcomes in this method: nothing malfunctions, so nothing is ever investigated,
-            // while the gate stays permanently inactive and a rotated key is never picked up.
-            _log.Error(
-                "No IMeshPskProvider was supplied to this actor; the known-cluster gate will NEVER "
-                + "be published and cached per-cluster keys will NEVER be dropped. Inbound mesh acks "
-                + "stay exposed to the pre-authentication secret-store cost the gate removes, and a "
-                + "rotated key needs a central restart. Check the ControlPlane registration");
-        }
 
         // Started in EVERY mode. The refresh is not transport state: it is central's ClusterNode
         // inventory, and the known-cluster gate it feeds protects an endpoint mapped by PORT, not by
@@ -281,33 +286,75 @@ public sealed class CentralCommunicationActor : ReceiveActor, IWithTimers
     /// <typeparam name="T">The dependency's type.</typeparam>
     /// <param name="factory">The factory, or <see langword="null"/> when nothing was supplied.</param>
     /// <param name="name">The dependency's name, for the log.</param>
+    /// <param name="firstUse">
+    ///     <see langword="false"/> for the eager <see cref="PreStart"/> call, <see langword="true"/>
+    ///     for the retry the memoized <see cref="Dialer"/>/<see cref="PskProvider"/> properties make
+    ///     on first use. Controls wording only, deliberately at the SAME (Debug) severity either
+    ///     way — see the remarks on why the loud signal lives elsewhere.
+    /// </param>
     /// <returns>The resolved dependency, or <see langword="null"/>.</returns>
     /// <remarks>
-    ///     Catching is the point. A throw out of <see cref="PreStart"/> is an actor failure, and the
+    ///     <para>
-    ///     supervisor's answer to that is to restart — which calls <see cref="PreStart"/> again, and
+    ///         Catching is the point. A throw out of <see cref="PreStart"/> is an actor failure, and
-    ///     a broken DI graph is not a transient condition. That is an unbounded restart loop on the
+    ///         the supervisor's answer to that is to restart — which calls <see cref="PreStart"/>
-    ///     node's command boundary, taking the transport-independent ack path down with it. Logging
+    ///         again, and a broken DI graph is not a transient condition. That is an unbounded
-    ///     and continuing leaves the ack path serving and hands the two null guards below a genuine
+    ///         restart loop on the node's command boundary, taking the transport-independent ack
-    ///     absence to report, which is the same outcome as never having been wired.
+    ///         path down with it. Logging and continuing leaves the ack path serving.
+    ///     </para>
+    ///     <para>
+    ///         <b>Never logs above Debug, on EITHER call site.</b> From inside this method, a
+    ///         PreStart resolve losing the starter-ordering race and a genuinely broken factory are
+    ///         indistinguishable — both return null. Only the CALLER can tell them apart, because
+    ///         only the caller knows whether a value came back after the retry the memoized
+    ///         properties perform. So the loud, operator-facing signal is deliberately NOT here: it
+    ///         is at the two places that consume a still-null result after that retry —
+    ///         <see cref="DispatchOverGrpc"/> for the dialer (already existed, unchanged) and
+    ///         <see cref="PublishKnownClusters"/> for the PSK provider (added by this fix, guarded
+    ///         to once per incarnation because that call site runs on a timer forever, where
+    ///         <see cref="DispatchOverGrpc"/> only runs once per command).
+    ///     </para>
     /// </remarks>
-    private T? Resolve<T>(Func<T?>? factory, string name)
+    private T? Resolve<T>(Func<T?>? factory, string name, bool firstUse)
         where T : class
     {
         if (factory is null)
-            return null;
+            return null; // Never supplied — not a resolve failure, nothing to report at either call site.
 
+        T? result;
         try
         {
-            return factory();
+            result = factory();
         }
         catch (Exception ex)
         {
-            _log.Error(
+            LogUnresolved(name, firstUse, ex);
-                ex,
-                "Failed to resolve {Dependency} for the mesh command boundary; continuing without "
-                + "it. The guards below report what that costs", name);
             return null;
         }
+
+        if (result is null)
+            LogUnresolved(name, firstUse, null);
+
+        return result;
+    }
+
+    private void LogUnresolved(string name, bool firstUse, Exception? ex)
+    {
+        if (firstUse)
+        {
+            _log.Debug(
+                ex,
+                "{Dependency} is still not resolvable on the first-use retry; continuing without "
+                + "it for now. Whether this is worth an operator-facing signal is the caller's call",
+                name);
+        }
+        else
+        {
+            _log.Debug(
+                ex,
+                "{Dependency} was not yet resolvable at PreStart — likely a starter-ordering race "
+                + "with a later starter that has not finished registering yet; will retry on first "
+                + "use", name);
+        }
     }
 
     /// <inheritdoc />
@@ -805,11 +852,42 @@ public sealed class CentralCommunicationActor : ReceiveActor, IWithTimers
     ///         invalidating only departed clusters would serve the pre-rotation key forever. The cost
     ///         is one store read per cluster per refresh — the cache holds a single entry per cluster.
     ///     </para>
+    ///     <para>
+    ///         <b>This is the PSK provider's "first use" call site.</b> <see cref="PskProvider"/> is
+    ///         evaluated exactly ONCE per call (not once per statement — the old two-call-site shape
+    ///         doubled the memoized property's retry rate for no benefit) and its result reused for
+    ///         both calls below. A still-null result here means the property's own retry, on top of
+    ///         PreStart's original attempt, has ALSO failed — the genuinely permanent absence — so
+    ///         this is where that gets reported loudly, guarded to once per incarnation because this
+    ///         handler runs on the contact-refresh timer for the actor's entire life and an unguarded
+    ///         Error here would repeat every <c>ContactRefreshSeconds</c> forever.
+    ///     </para>
     /// </remarks>
     private void PublishKnownClusters(ContactsLoaded msg)
     {
-        PskProvider?.SetKnownClusters(msg.ClusterIds);
+        var pskProvider = PskProvider;
-        PskProvider?.InvalidateAll();
+        if (pskProvider is null)
+        {
+            // Gated on a factory having been supplied at all: a never-supplied factory is a
+            // deliberate wiring/test choice Resolve() already stayed silent about (see its
+            // remarks), not a resolve failure, so it earns no Error here either.
+            if (_pskProviderFactory is not null && !_pskProviderAbsenceReported)
+            {
+                _pskProviderAbsenceReported = true;
+                _log.Error(
+                    "No IMeshPskProvider is resolvable for this actor, even after a first-use retry; "
+                    + "the known-cluster gate will NEVER be published and cached per-cluster keys "
+                    + "will NEVER be dropped. Inbound mesh acks stay exposed to the "
+                    + "pre-authentication secret-store cost the gate removes, and a rotated key "
+                    + "needs a central restart. Check the ControlPlane registration wires "
+                    + "IMeshPskProvider (this will not be logged again this incarnation)");
+            }
+
+            return;
+        }
+
+        pskProvider.SetKnownClusters(msg.ClusterIds);
+        pskProvider.InvalidateAll();
     }
 
     /// <summary>Stops a cluster's existing client and creates a replacement for its new contact set.</summary>

tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/CentralCommunicationActorTests.cs

@@ -820,13 +820,125 @@ public class CentralCommunicationActorTests : ControlPlaneActorTestBase
             dialer: null,
             pskProvider: null));
 
-        // Filtered on the DISPATCH message's exact phrase: PreStart logs its own error about the same
+        // A never-supplied factory (dialer: null here) is silent at PreStart and on every retry —
-        // mis-wiring, and a looser filter races it into a second match.
+        // see Resolve's remarks — so this dispatch-time Error is the ONLY log line the mis-wiring
+        // produces. That is what makes the plain "no command dialer is wired" phrase safe to match
+        // without a second source racing it, unlike before this actor stopped double-reporting the
+        // same absence at two severities.
         EventFilter.Error(contains: "no command dialer is wired").ExpectOne(
             TimeSpan.FromSeconds(5),
             () => actor.Tell(new MeshCommand(DeploymentsTopic, NewDispatch())));
     }
 
+    // ------------------------------------------------------------------ PreStart resolve-race logging
+    //
+    // PreStart's eager resolve of IMeshCommandDialer/IMeshPskProvider loses a millisecond-wide race
+    // against the Akka builder's remaining starters on essentially every admin boot (live gates: 1A
+    // 2/3 boots, 1B 4/4 boots) and self-heals at the memoized properties' first use. The two facts
+    // below are the headline pin: a healthy boot must produce ZERO Warning/Error from this actor, and
+    // a GENUINELY broken factory must still be reported loudly, exactly once.
+
+    [Fact]
+    public void A_healthy_boot_produces_no_warning_or_error_even_though_PreStart_loses_the_resolve_race()
+    {
+        // Models the ordinary boot: both factories throw on their FIRST invocation (PreStart, which
+        // loses the race) and succeed on every subsequent one (the memoized properties' first-use
+        // retry, long after every starter has finished). This must be silent — no Warning, no Error
+        // — from PreStart all the way through the first contact load and the first dispatch, or a
+        // soak error-grep on a healthy rig is impossible.
+        var factory = NewInMemoryDbFactory();
+        SeedGrpcCluster(factory, "C1", ("host-a:4053", "host-a", 4056, true, false));
+        var dialer = new RecordingDialer();
+        var psk = new RecordingPskProvider();
+        var dialerCalls = 0;
+        var pskCalls = 0;
+
+        IMeshCommandDialer? DialerFactory()
+        {
+            dialerCalls++;
+            return dialerCalls == 1 ? throw new InvalidOperationException("starter-ordering race") : dialer;
+        }
+
+        IMeshPskProvider? PskFactory()
+        {
+            pskCalls++;
+            return pskCalls == 1 ? throw new InvalidOperationException("starter-ordering race") : psk;
+        }
+
+        IActorRef? actor = null;
+        EventFilter.Warning().And.Error().Expect(0, TimeSpan.FromSeconds(5), () =>
+        {
+            actor = Sys.ActorOf(CentralCommunicationActor.Props(
+                factory,
+                GrpcMode(),
+                new RecordingClientFactory(() => CreateTestProbe()),
+                () => null,
+                DialerFactory,
+                PskFactory));
+
+            // First use of the PSK provider: the contact-refresh timer's initial (TimeSpan.Zero)
+            // tick, observed via the gate publish.
+            AwaitCondition(() => psk.KnownClusterPublications.Count >= 1, TimeSpan.FromSeconds(5));
+
+            // First use of the dialer: an ordinary dispatch, retried until the contact load (which
+            // races this on the same timer tick) has adopted the gRPC target set.
+            AwaitCondition(() =>
+            {
+                actor!.Tell(new MeshCommand(DeploymentsTopic, NewDispatch()));
+                return dialer.Calls.Count >= 1;
+            }, TimeSpan.FromSeconds(5));
+        });
+
+        // Both retries actually happened — this fact is not vacuously true because the factories
+        // never got a second chance to run.
+        dialerCalls.ShouldBeGreaterThanOrEqualTo(2);
+        pskCalls.ShouldBeGreaterThanOrEqualTo(2);
+    }
+
+    [Fact]
+    public void A_permanently_unresolvable_pskProvider_is_reported_once_per_incarnation_not_once_per_refresh()
+    {
+        // The counterpart pin: a factory that NEVER succeeds is the genuinely permanent absence and
+        // must still be loud — but PublishKnownClusters runs on the contact-refresh timer for the
+        // actor's whole life, so an unguarded Error would repeat every ContactRefreshSeconds forever.
+        // Guarded exactly like _warnedPortlessNodes: once per incarnation, not once per refresh.
+        var factory = NewInMemoryDbFactory();
+        SeedGrpcCluster(factory, "C1", ("host-a:4053", "host-a", 4056, true, false));
+        var dialer = new RecordingDialer();
+
+        IActorRef actor = null!;
+        EventFilter.Error(contains: "will NEVER be published").ExpectOne(TimeSpan.FromSeconds(5), () =>
+        {
+            actor = Sys.ActorOf(CentralCommunicationActor.Props(
+                factory,
+                GrpcMode(),
+                new RecordingClientFactory(() => CreateTestProbe()),
+                () => null,
+                () => dialer,
+                pskProvider: () => throw new InvalidOperationException("permanently broken")));
+
+            // Proof the FIRST contact load actually completed (the gRPC target set is adopted
+            // before the gate publish this Error guards — see HandleContactsLoaded), rather than
+            // relying on timing alone.
+            AwaitCondition(() =>
+            {
+                actor.Tell(new MeshCommand(DeploymentsTopic, NewDispatch()));
+                return dialer.Calls.Count >= 1;
+            }, TimeSpan.FromSeconds(5));
+        });
+
+        // A SECOND contact load must NOT repeat it.
+        EventFilter.Error(contains: "will NEVER be published").Expect(0, TimeSpan.FromSeconds(5), () =>
+        {
+            actor.Tell(new CentralCommunicationActor.RefreshContacts());
+            AwaitCondition(() =>
+            {
+                actor.Tell(new MeshCommand(DeploymentsTopic, NewDispatch()));
+                return dialer.Calls.Count >= 2;
+            }, TimeSpan.FromSeconds(5));
+        });
+    }
+
     private static void SetGrpcPort(
         IDbContextFactory<OtOpcUaConfigDbContext> factory, string nodeId, int? grpcPort)
     {