diff --git a/archreview/plans/R3-02-stale-good-family-plan.md b/archreview/plans/R3-02-stale-good-family-plan.md index af4c66aa..9eca0c0f 100644 --- a/archreview/plans/R3-02-stale-good-family-plan.md +++ b/archreview/plans/R3-02-stale-good-family-plan.md @@ -877,3 +877,34 @@ this plan each appended last: fixture, and it is the only evidence that the identical-value recovery works end to end on a real device. Recipe unchanged in §Live gate; the constant HR[5] vs auto-incrementing HR[100] pairing is what makes it non-vacuous. + +--- + +## Review outcome (verdict MERGE, two Low items applied) + +Both were **real** — each is a place where a polled/observed surface disagreed with what the contract +says, i.e. the same class of bug this plan exists to close, one hop further out. Applied TDD, one commit. + +1. **`CalculationDriver.ReadOne` guarded on `!st.HasValue`** — so a tag whose only publish was an + inputs-Bad report (no value of its own) read back `BadWaitingForInitialData` while its subscriber had + been told `BadNoCommunication`. The guard is now `!st.HasPublished`, which is the state that actually + means "nothing has ever been said about this tag". + - RED: new `ReadAsync_after_an_inputs_Bad_with_no_prior_value_reports_the_bad_status` ⇒ + `Shouldly.ShouldAssertException : read[0].StatusCode should be 2150694912u`. + - The pre-existing `An_unevaluated_tag_still_reads_BadWaitingForInitialData` is the control for the + other side of the same guard and stayed green. +2. **`VirtualTagActor.OnInputsBad` metered `VirtualTagEval{outcome=inputs-bad}` above the + `AllDependenciesArrived()` return** — so ordinary cold start produced an "inputs bad" measurement per + trigger. The `Add` moved below **both** guards (readiness and transition-once), so the counter now + measures tags that actually report. + - RED: new `The_inputs_bad_counter_does_not_tick_during_warm_up` ⇒ + `Shouldly.ShouldAssertException : meter.Count("inputs-bad") should be 0`. + - The absence half carries a **positive control in the same test** (completing the dep set ⇒ exactly + one measurement), so it cannot pass for want of a working `MeterListener`. + +**Suites after the fixes:** `Driver.Calculation.Tests` **65/65**; `Runtime.Tests` `~VirtualTag` +**59/59**; `Core.ScriptedAlarms.Tests` **94/94**. + +**STATUS.md corrected:** the anonymous Runtime.Tests flake is +`DriverHostActorNativeAlarmAckRoutingTests.RouteNativeAlarmAck_routes_to_driver_AcknowledgeAsync_with_principal` +— untouched by this branch, known #500 profile, 3× green in isolation per the reviewer. diff --git a/archreview/plans/STATUS.md b/archreview/plans/STATUS.md index b6d80770..eb3019d7 100644 --- a/archreview/plans/STATUS.md +++ b/archreview/plans/STATUS.md @@ -527,9 +527,11 @@ watchdog; calc tags and virtual tags **hold** while an input is Bad and report t a script that relied on receiving `null` for a dead input no longer runs while it is Bad. **Test-suite state at `62c5bc3a`:** full-solution unit sweep green. `Runtime.Tests` 672 passed / 3 -skipped on four separate runs; one further run showed a **single** failure whose name was lost to an -output filter — consistent with the known #500 flake profile (~13 %/run) and not reproduced in four -subsequent full runs. No pre-existing red on the base commit. +skipped on four separate runs; one further run showed a single failure — +`DriverHostActorNativeAlarmAckRoutingTests.RouteNativeAlarmAck_routes_to_driver_AcknowledgeAsync_with_principal` +(named by the reviewer, who saw it once and then 3× green in isolation). It is untouched by this branch +and matches the known #500 flake profile (~13 %/run); not reproduced in four subsequent full runs. No +pre-existing red on the base commit. **NOT done here — T19, the live gate**, which is the merge-blocking rig session (docker-dev + the Modbus `standard` fixture: constant HR[5] proves the force-republish, HR[100] is the positive control; plus the diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs index 66e5b663..99ee773b 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation/CalculationDriver.cs @@ -394,7 +394,11 @@ public sealed class CalculationDriver : IDriver, IDependencyConsumer, ISubscriba var now = DateTime.UtcNow; lock (_lock) { - if (!_stateByRawPath.TryGetValue(reference, out var st) || !st.HasValue) + // Gated on HAS PUBLISHED, not on "has a value": a tag whose only publish was an inputs-Bad + // report has no value of its own, and answering BadWaitingForInitialData for it would tell a + // polled reader "never observed" while the subscriber on the same node had been told + // BadNoCommunication. Something HAS been observed about such a tag — that its input is dead. + if (!_stateByRawPath.TryGetValue(reference, out var st) || !st.HasPublished) return new DataValueSnapshot(null, StatusBadWaitingForInitialData, null, now); // Exactly what the subscriber was last told — including a propagated input sub-code. Deriving // it from a two-state flag here would make a read disagree with the subscription over the diff --git a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs index 9b33d846..c2c7a8fd 100644 --- a/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs +++ b/src/Server/ZB.MOM.WW.OtOpcUa.Runtime/VirtualTags/VirtualTagActor.cs @@ -328,11 +328,14 @@ public sealed class VirtualTagActor : ReceiveActor /// The triggering change's timestamp, stamped on the result. private void OnInputsBad(uint worstInputStatus, DateTime timestampUtc) { - OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair("outcome", "inputs-bad")); - if (!AllDependenciesArrived()) return; if (_hasPublished && _lastPublishedStatus == worstInputStatus) return; + // Metered BELOW both guards, so the counter measures tags that actually REPORT Bad inputs. Above + // them it also counted every warm-up trigger — a dependency that has simply not arrived yet — which + // is ordinary cold start, and burying the real signal in it is how a counter stops being trusted. + OtOpcUaTelemetry.VirtualTagEval.Add(1, new KeyValuePair("outcome", "inputs-bad")); + _hasPublished = true; _lastPublishedStatus = worstInputStatus; Context.Parent.Tell(new EvaluationResult( diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs index 05a48dfb..73f6f012 100644 --- a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.Calculation.Tests/CalculationDriverInputQualityTests.cs @@ -270,6 +270,38 @@ public sealed class CalculationDriverInputQualityTests read[0].Value.ShouldBe(bad.Snapshot.Value); } + /// + /// A tag whose ONLY publish was inputs-Bad — it never produced a value — must read back that Bad + /// status, not BadWaitingForInitialData. Guarding the read on "has a value" rather than + /// "has published" made a polled read say "never polled" while the subscriber on the same node had + /// been told BadNoCommunication: the two clients disagree, and the read is the one that + /// lies (something HAS been observed about this tag — that its input is dead). + /// + [Fact] + public async Task ReadAsync_after_an_inputs_Bad_with_no_prior_value_reports_the_bad_status() + { + var (driver, published, _) = Build(CalcTag(SumTag, SumScript)); + await driver.InitializeAsync("{}", TestContext.Current.CancellationToken); + + // The first thing that ever happens to this tag is a dead input — no successful evaluation, so + // there is no last value to carry. + driver.OnDependencyValue("src/a", null, StatusBadNoCommunication, DateTime.UtcNow); + driver.OnDependencyValue("src/b", 20.0, StatusGood, DateTime.UtcNow); + await Settle(driver); + + published.Count.ShouldBe(1); + published.TryDequeue(out var bad).ShouldBeTrue(); + bad!.Snapshot.StatusCode.ShouldBe(StatusBadNoCommunication); + bad.Snapshot.Value.ShouldBeNull(); + + var read = await driver.ReadAsync([SumTag], TestContext.Current.CancellationToken); + + read[0].StatusCode.ShouldBe(StatusBadNoCommunication); + read[0].StatusCode.ShouldNotBe(StatusBadWaitingForInitialData, + "something HAS been observed about this tag — that its input is dead"); + read[0].Value.ShouldBeNull(); + } + /// A never-evaluated tag still reads BadWaitingForInitialData (regression). [Fact] public async Task An_unevaluated_tag_still_reads_BadWaitingForInitialData() diff --git a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/VirtualTagActorInputQualityTests.cs b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/VirtualTagActorInputQualityTests.cs index 039c380e..6cb014fb 100644 --- a/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/VirtualTagActorInputQualityTests.cs +++ b/tests/Server/ZB.MOM.WW.OtOpcUa.Runtime.Tests/VirtualTags/VirtualTagActorInputQualityTests.cs @@ -1,8 +1,10 @@ +using System.Diagnostics.Metrics; using Akka.Actor; using Shouldly; using Xunit; 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.Core.Abstractions; using ZB.MOM.WW.OtOpcUa.Runtime.Tests.Harness; @@ -149,6 +151,35 @@ public sealed class VirtualTagActorInputQualityTests : RuntimeActorTestBase parent.ExpectNoMsg(TimeSpan.FromMilliseconds(400)); } + /// + /// The inputs-bad outcome counter must tick only when a tag actually reports Bad + /// inputs — not on every warm-up trigger, where a declared dependency simply has not arrived yet. + /// Metering above the readiness gate turns ordinary cold start into a stream of "inputs bad" + /// measurements, which is exactly the noise that makes an operator stop trusting the counter. + /// The absence half is paired with a positive control in the same test — the counter DOES + /// tick once the tag reports — so "no measurements" can never pass for want of a working listener. + /// + [Fact] + public void The_inputs_bad_counter_does_not_tick_during_warm_up() + { + var parent = CreateTestProbe(); + var actor = parent.ChildActorOf(VirtualTagActor.Props( + "vt-1", "a + b", evaluator: new CountingSumEvaluator(), dependencyRefs: ["a", "b"])); + using var meter = new OutcomeRecorder(); + + // Warm-up: "b" has never arrived, so this is cold start, not a fault. + actor.Tell(new VirtualTagActor.DependencyValueChanged("a", null, DateTime.UtcNow, OpcUaStatus.BadNoCommunication)); + parent.ExpectNoMsg(TimeSpan.FromMilliseconds(400)); + + meter.Count("inputs-bad").ShouldBe(0, "warm-up is not an inputs-bad report"); + + // Positive control: once every dep has arrived, the tag reports — and the counter ticks. + actor.Tell(new VirtualTagActor.DependencyValueChanged("b", 32, DateTime.UtcNow)); + parent.ExpectMsg(PresenceBudget) + .StatusCode.ShouldBe(OpcUaStatus.BadNoCommunication); + AwaitCondition(() => meter.Count("inputs-bad") == 1, TimeSpan.FromSeconds(3)); + } + /// /// A deploy's ReassertValue re-emits the LAST PUBLISHED status, so a VT whose input is /// comms-lost re-asserts BadNoCommunication onto the freshly-materialised node rather than @@ -207,6 +238,49 @@ public sealed class VirtualTagActorInputQualityTests : RuntimeActorTestBase evaluator.Calls.ShouldBe(callsBefore); } + /// + /// Counts otopcua.virtualtag.eval measurements by their outcome tag. + /// A sees every measurement in the process, and this counter is + /// hot across the assembly — so the assertions above are scoped to the inputs-bad outcome, + /// which only this suite produces (nothing else drives a Bad dependency), and the absence + /// assertion is paired with a positive control rather than standing alone. + /// + private sealed class OutcomeRecorder : IDisposable + { + private readonly MeterListener _listener; + private readonly List _outcomes = new(); + private readonly object _gate = new(); + + public OutcomeRecorder() + { + _listener = new MeterListener + { + InstrumentPublished = (instrument, listener) => + { + if (instrument.Meter.Name == OtOpcUaTelemetry.MeterName + && instrument.Name == "otopcua.virtualtag.eval") + listener.EnableMeasurementEvents(instrument); + }, + }; + _listener.SetMeasurementEventCallback((_, _, tags, _) => + { + foreach (var tag in tags) + { + if (tag.Key != "outcome" || tag.Value is not string outcome) continue; + lock (_gate) _outcomes.Add(outcome); + } + }); + _listener.Start(); + } + + public int Count(string outcome) + { + lock (_gate) return _outcomes.Count(o => o == outcome); + } + + public void Dispose() => _listener.Dispose(); + } + /// /// Sums the dependency values, counts its invocations, and records the status code the actor /// handed it for "a" — so a test can assert both that the script did NOT run and that, when it