diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.ControlPlane/Communication/CentralCommunicationActor.cs b/src/Server/ZB.MOM.WW.OtOpcUa.ControlPlane/Communication/CentralCommunicationActor.cs index e25342f4..b72c44ac 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.ControlPlane/Communication/CentralCommunicationActor.cs +++ b/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 _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 _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) - { - // Not a fatal throw: the ack path (HandleApplyAck) is transport-independent and still - // works, so taking the actor down would turn a command-plane mis-wiring into an ack - // outage as well. Every dispatch logs its own error, so this cannot go unnoticed. - _log.Error( - "Mesh transport is Grpc but no command dialer was supplied to this actor; EVERY " - + "central→node command will be dropped. Check the ControlPlane registration wires " - + "IMeshCommandDialer"); - } - - 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"); - } + // 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 — + // reporting it loudly here would be the exact false alarm this fix removes, on nearly + // every boot. A retry that ALSO fails — the genuinely permanent absence — is reported + // loudly where it actually costs something instead: DispatchOverGrpc for the dialer (every + // dropped command, unchanged — see the EventFilter pin on that message), and + // PublishKnownClusters for the PSK provider (once per incarnation, not once per refresh + // forever, since that handler runs on the contact-refresh timer for the actor's whole + // life). // 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 /// The dependency's type. /// The factory, or when nothing was supplied. /// The dependency's name, for the log. + /// + /// for the eager call, + /// for the retry the memoized / 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. + /// /// The resolved dependency, or . /// - /// Catching is the point. A throw out of is an actor failure, and the - /// supervisor's answer to that is to restart — which calls again, and - /// a broken DI graph is not a transient condition. That is an unbounded restart loop on the - /// node's command boundary, taking the transport-independent ack path down with it. Logging - /// and continuing leaves the ack path serving and hands the two null guards below a genuine - /// absence to report, which is the same outcome as never having been wired. + /// + /// Catching is the point. A throw out of is an actor failure, and + /// the supervisor's answer to that is to restart — which calls + /// again, and a broken DI graph is not a transient condition. That is an unbounded + /// restart loop on the node's command boundary, taking the transport-independent ack + /// path down with it. Logging and continuing leaves the ack path serving. + /// + /// + /// Never logs above Debug, on EITHER call site. 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 — + /// for the dialer (already existed, unchanged) and + /// for the PSK provider (added by this fix, guarded + /// to once per incarnation because that call site runs on a timer forever, where + /// only runs once per command). + /// /// - private T? Resolve(Func? factory, string name) + private T? Resolve(Func? 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( - ex, - "Failed to resolve {Dependency} for the mesh command boundary; continuing without " - + "it. The guards below report what that costs", name); + LogUnresolved(name, firstUse, ex); 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); + } } /// @@ -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. /// + /// + /// This is the PSK provider's "first use" call site. 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 ContactRefreshSeconds forever. + /// /// private void PublishKnownClusters(ContactsLoaded msg) { - PskProvider?.SetKnownClusters(msg.ClusterIds); - PskProvider?.InvalidateAll(); + var pskProvider = PskProvider; + 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(); } /// Stops a cluster's existing client and creates a replacement for its new contact set. diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/CentralCommunicationActorTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/CentralCommunicationActorTests.cs index 9004bf2d..423e0b3d 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.ControlPlane.Tests/Communication/CentralCommunicationActorTests.cs +++ b/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 - // mis-wiring, and a looser filter races it into a second match. + // A never-supplied factory (dialer: null here) is silent at PreStart and on every retry — + // 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 factory, string nodeId, int? grpcPort) {