fix(focas): the fixed-tree loop reports device silence to driver health (R07:H15)

The fixed-tree loop swallowed every failure at Debug and never touched health, so a driver serving only FIXED: tags (Identity/Axes/Program/Status, the typical FOCAS shape) read Healthy on /hosts with every node Bad and the #527 watchdog could never fire. The fixed tree is now a third health path beside the value and alarm paths, combined in GetHealth (worst state, latest LastSuccessfulRead): - an answered bootstrap / axis pass clears the device's failure and advances LastSuccessfulRead; - a transport failure degrades the driver once the device has been silent past the same staleness budget that turns its values Bad (from its last answer, or from loop start when it never answered), with LastSuccessfulRead frozen; - a CNC refusal (non-OK rc) is not a comms loss: it clears the failure and credits nothing. Refs #740 Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT
2026-10-22 14:11:25 -04:00
parent 12b981dc1b
commit 6423ed272f
2 changed files with 207 additions and 12 deletions
@@ -562,24 +562,27 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
    }

    /// <inheritdoc />
-    // The worst of the value path (_health) and the alarm path (_alarmTransportFailures),
-    // computed together. LastSuccessfulRead is the later of the two paths' last successes: while either
-    // path still reads, the comms-loss watchdog stays quiet; when both have stopped it is frozen.
-    // Faulted / Unknown / Initializing come from the value (lifecycle) path unchanged.
+    // The worst of the value path (_health), the alarm path (_alarmTransportFailures) and the fixed-tree path
+    // (_fixedTreeFailures), computed together. LastSuccessfulRead is the latest of the three paths' last
+    // successes: while any path still reads, the comms-loss watchdog stays quiet; when all have stopped it is
+    // frozen. Faulted / Unknown / Initializing come from the value (lifecycle) path unchanged.
    public DriverHealth GetHealth()
    {
        var value = Volatile.Read(ref _health);
-        var ticks = Interlocked.Read(ref _alarmLastSuccessTicks);
-        DateTime? alarmLast = ticks == 0 ? null : new DateTime(ticks, DateTimeKind.Utc);
-        var last = value.LastSuccessfulRead is { } v && (alarmLast is null || v >= alarmLast) ? v : alarmLast;
+        var last = Latest(Latest(value.LastSuccessfulRead, Stamp(Interlocked.Read(ref _alarmLastSuccessTicks))),
+            Stamp(Interlocked.Read(ref _fixedTreeLastSuccessTicks)));

        if (value.State is not (DriverState.Healthy or DriverState.Degraded)) return value;
-        if (value.State == DriverState.Healthy && !_alarmTransportFailures.IsEmpty)
-        {
-            var reason = _alarmTransportFailures.OrderBy(kv => kv.Key, StringComparer.OrdinalIgnoreCase).First().Value;
+        if (value.State == DriverState.Healthy
+            && (FirstFailure(_alarmTransportFailures) ?? FirstFailure(_fixedTreeFailures)) is { } reason)
            return new DriverHealth(DriverState.Degraded, last, reason);
-        }
        return value.LastSuccessfulRead == last ? value : value with { LastSuccessfulRead = last };
+
+        static DateTime? Stamp(long ticks) => ticks == 0 ? null : new DateTime(ticks, DateTimeKind.Utc);
+        static DateTime? Latest(DateTime? a, DateTime? b) => a is null ? b : b is null || a >= b ? a : b;
+        static string? FirstFailure(ConcurrentDictionary<string, string> failures) => failures.IsEmpty
+            ? null
+            : failures.OrderBy(kv => kv.Key, StringComparer.OrdinalIgnoreCase).Select(kv => kv.Value).FirstOrDefault();
    }

    /// <summary>Gets the number of configured devices.</summary>
@@ -1290,6 +1293,7 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
        // Each optional call is attempted once; failures (EW_FUNC / EW_NOOPT / EW_VERSION)
        // record the capability as unsupported and suppress the corresponding nodes
        // in DiscoverAsync + the poll loop.
+        state.FixedTreeStartedUtc = DateTime.UtcNow;
        while (!ct.IsCancellationRequested && state.FixedTreeCache is null)
        {
            try
@@ -1320,6 +1324,7 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
                // so stamp liveness here as well as per tick, or a CNC whose axis poll never
                // succeeds would serve a perfectly valid sysinfo as stale.
                state.LastFixedPollUtc = DateTime.UtcNow;
+                NoteFixedTreeAnswered(state);
                // Published LAST (release write): LastStatus is the field callers watch for "the first
                // answer is in", and an authored FIXED:Status/* read is only servable once
                // FixedTreeCache and LastFixedPollUtc are set (TryReadFixedTreeOnDevice). Publishing it
@@ -1331,6 +1336,7 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
            {
                _logger.LogDebug(ex, "FOCAS fixed-tree bootstrap failed for {Host} — retrying",
                    state.Options.HostAddress);
+                NoteFixedTreeFailed(state, ex);
                try { await Task.Delay(TimeSpan.FromSeconds(2), ct).ConfigureAwait(false); }
                catch (OperationCanceledException) { return; }
            }
@@ -1379,6 +1385,8 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
                // of the loop: EnsureConnectedAsync can hand back a cached handle without any wire
                // traffic, so it alone does not prove the CNC is still there.
                state.LastFixedPollUtc = DateTime.UtcNow;
+                // …and it is the driver's evidence of life too: a fixed-only driver has no value read to credit.
+                NoteFixedTreeAnswered(state);

                // Servo loads + spindle loads — both return bulk arrays, so folding
                // into the axis cadence is cheap. Each is gated by the bootstrap
@@ -1474,6 +1482,8 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
                /* next tick retries — transient blips are expected */
                _logger.LogDebug(ex, "FOCAS fixed-tree poll tick failed for {Host}",
                    state.Options.HostAddress);
+                // …but a sustained silence is a comms loss, and nothing else will report it for a fixed-only driver.
+                NoteFixedTreeFailed(state, ex);
            }

            try { await Task.Delay(_options.FixedTree.PollInterval, ct).ConfigureAwait(false); }
@@ -1635,7 +1645,7 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
    {
        var polledUtc = state.LastFixedPollUtc;
        if (polledUtc is null) return null;
-        var status = now - polledUtc.Value > FixedTreeStaleAfter(_options.FixedTree.PollInterval)
+        var status = now - polledUtc.Value > FixedTreeStaleBudget
            ? FocasStatusMapper.BadCommunicationError
            : FocasStatusMapper.Good;
        var sourceUtc = polledUtc.Value;
@@ -1850,6 +1860,55 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
    {
        _alarmTransportFailures.Clear();
        Interlocked.Exchange(ref _alarmLastSuccessTicks, 0);
+        _fixedTreeFailures.Clear();
+        Interlocked.Exchange(ref _fixedTreeLastSuccessTicks, 0);
+    }
+
+    /// <summary>
+    ///     The FIXED-TREE half of driver health: device host → why its fixed-tree loop has had no answer for longer
+    ///     than the staleness budget. Kept apart from <see cref="_health"/> like the alarm path, and for the same
+    ///     reason — a driver serving only <c>FIXED:</c> tags has no value read to degrade it, so before this it
+    ///     read Healthy on <c>/hosts</c> with every node Bad and the #527 watchdog could never fire.
+    /// </summary>
+    private readonly ConcurrentDictionary<string, string> _fixedTreeFailures = new(StringComparer.OrdinalIgnoreCase);
+
+    /// <summary>UTC ticks of the last answered fixed-tree poll on any device (0 = none).</summary>
+    private long _fixedTreeLastSuccessTicks;
+
+    /// <summary>Test seam: replaces the fixed-tree staleness budget (production derives it from the poll interval).</summary>
+    internal TimeSpan? FixedTreeStaleBudgetOverride { get; init; }
+
+    /// <summary>
+    ///     How long a device's fixed tree may go unanswered before its values read Bad AND the driver degrades —
+    ///     one budget for both, so the node quality and the health surface cannot disagree.
+    /// </summary>
+    private TimeSpan FixedTreeStaleBudget =>
+        FixedTreeStaleBudgetOverride ?? FixedTreeStaleAfter(_options.FixedTree.PollInterval);
+
+    /// <summary>An answered fixed-tree pass of <paramref name="state"/>: clears its failure, advances LastSuccessfulRead.</summary>
+    private void NoteFixedTreeAnswered(DeviceState state)
+    {
+        _fixedTreeFailures.TryRemove(state.Options.HostAddress, out _);
+        Interlocked.Exchange(ref _fixedTreeLastSuccessTicks, DateTime.UtcNow.Ticks);
+    }
+
+    /// <summary>
+    ///     A failed fixed-tree tick. A CNC REFUSAL (non-OK rc, transport fine) is not a comms loss and clears any
+    ///     failure without crediting a read; a transport failure degrades the driver only once the device has been
+    ///     silent past <see cref="FixedTreeStaleBudget"/> (measured from its last answer, or from loop start when
+    ///     it never answered), so one dropped tick on a slow control does not flap <c>/hosts</c>.
+    /// </summary>
+    private void NoteFixedTreeFailed(DeviceState state, Exception error)
+    {
+        if (FocasAlarmProjection.IsCncRefusal(error))
+        {
+            _fixedTreeFailures.TryRemove(state.Options.HostAddress, out _);
+            return;
+        }
+        var since = state.LastFixedPollUtc ?? state.FixedTreeStartedUtc;
+        if (DateTime.UtcNow - since > FixedTreeStaleBudget)
+            _fixedTreeFailures[state.Options.HostAddress] =
+                $"FOCAS fixed-tree poll of {state.Options.HostAddress} has had no answer since {since:O}: {error.Message}";
    }

    /// <summary>
@@ -2082,6 +2141,9 @@ public sealed class FocasDriver : IDriver, IReadable, IWritable, ITagDiscovery,
        ///     it falls outside <see cref="FixedTreeStaleAfter"/>.
        /// </remarks>
        public DateTime? LastFixedPollUtc { get; set; }
+
+        /// <summary>When this device's fixed-tree loop started — the silence origin for a device that never answered.</summary>
+        public DateTime FixedTreeStartedUtc { get; set; } = DateTime.UtcNow;
        /// <summary>
        ///     Gets the last fixed-tree snapshots by field name. Double-typed so axis
        ///     positions can carry the engineering-unit scale applied at
@@ -0,0 +1,133 @@
+using Shouldly;
+using Xunit;
+using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
+using ZB.MOM.WW.OtOpcUa.Driver.FOCAS;
+using ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Wire;
+
+namespace ZB.MOM.WW.OtOpcUa.Driver.FOCAS.Tests;
+
+/// <summary>
+///     #740 / R07:H15 — the fixed-tree loop swallowed every failure at Debug and never touched driver health, so a
+///     driver serving only <c>FIXED:</c> tags (Identity / Axes / Program / Status — the typical FOCAS shape) read
+///     Healthy on <c>/hosts</c> with every node Bad, and the #527 comms-loss watchdog could never fire. The loop
+///     now credits each answered axis pass (Healthy + LastSuccessfulRead) and, once a device has been silent past
+///     the fixed-tree staleness budget, degrades the driver with LastSuccessfulRead frozen.
+/// </summary>
+[Trait("Category", "Unit")]
+public sealed class FocasFixedTreeHealthTests
+{
+    private const string Host = "focas://10.0.0.5:8193";
+    private static readonly TimeSpan Stale = TimeSpan.FromMilliseconds(300);
+
+    /// <summary>A CNC that can be switched off (transport failure) or made to refuse the dynamic read.</summary>
+    private sealed class CncSwitch
+    {
+        public volatile bool Down;
+        public volatile bool Refuse;
+    }
+
+    private sealed class SwitchableCnc(CncSwitch sw) : FakeFocasClient
+    {
+        private bool Down => sw.Down;
+        private bool Refuse => sw.Refuse;
+
+        public override Task<FocasSysInfo> GetSysInfoAsync(CancellationToken ct) =>
+            Down ? throw new IOException("socket closed") : base.GetSysInfoAsync(ct);
+
+        public override Task<FocasDynamicSnapshot> ReadDynamicAsync(int axisIndex, CancellationToken ct)
+        {
+            if (Down) throw new IOException("socket closed");
+            if (Refuse) throw new FocasWireException("cnc_rddynamic2 refused", rc: 6);
+            return base.ReadDynamicAsync(axisIndex, ct);
+        }
+    }
+
+    private static FocasDriver FixedOnlyDriver(CncSwitch sw) => new(new FocasDriverOptions
+    {
+        Devices = [new FocasDeviceOptions(Host)],
+        RawTags = [FocasRawTags.Entry(new FocasTagDefinition("raw/X", Host, "FIXED:Axes/X/AbsolutePosition", FocasDataType.Float64))],
+        Probe = new FocasProbeOptions { Enabled = false },
+        FixedTree = new FocasFixedTreeOptions
+        {
+            PollInterval = TimeSpan.FromMilliseconds(20),
+            ProgramPollInterval = TimeSpan.Zero,
+            TimerPollInterval = TimeSpan.Zero,
+        },
+    }, "focas-fixed-health", new FakeFocasClientFactory { Customise = () => new SwitchableCnc(sw) })
+    {
+        FixedTreeStaleBudgetOverride = Stale,
+    };
+
+    /// <summary>
+    ///     Positive control first, then the outage: an answering CNC keeps the driver Healthy with a moving
+    ///     LastSuccessfulRead; a CNC that stops answering degrades it once the budget passes, with
+    ///     LastSuccessfulRead frozen (the watchdog's conjunction); and its return restores Healthy.
+    /// </summary>
+    [Fact]
+    public async Task Fixed_only_driver_degrades_when_its_cnc_disappears_and_recovers_when_it_returns()
+    {
+        var sw = new CncSwitch();
+        await using var drv = FixedOnlyDriver(sw);
+        await drv.InitializeAsync("{}", CancellationToken.None);
+        await WaitUntil(() => drv.GetDeviceState(Host)?.LastFixedPollUtc is not null);
+
+        var first = drv.GetHealth().LastSuccessfulRead;
+        await Task.Delay(100);
+        var healthy = drv.GetHealth();
+        healthy.State.ShouldBe(DriverState.Healthy);
+        healthy.LastSuccessfulRead!.Value.ShouldBeGreaterThan(first!.Value, "an answered axis pass is a successful read");
+
+        sw.Down = true;
+        await Task.Delay(100);
+        drv.GetHealth().State.ShouldBe(DriverState.Healthy, "a blip inside the staleness budget does not degrade");
+        await WaitUntil(() => drv.GetHealth().State == DriverState.Degraded);
+        var frozen = drv.GetHealth().LastSuccessfulRead;
+        await Task.Delay(150);
+        drv.GetHealth().State.ShouldBe(DriverState.Degraded);
+        drv.GetHealth().LastSuccessfulRead.ShouldBe(frozen, "LastSuccessfulRead must stay frozen while the CNC is silent");
+
+        sw.Down = false;
+        await WaitUntil(() => drv.GetHealth().State == DriverState.Healthy);
+        drv.GetHealth().LastSuccessfulRead!.Value.ShouldBeGreaterThan(frozen!.Value);
+    }
+
+    /// <summary>A CNC that is down from the start (bootstrap never succeeds) degrades once the budget passes.</summary>
+    [Fact]
+    public async Task Bootstrap_that_never_succeeds_degrades_the_driver()
+    {
+        var sw = new CncSwitch { Down = true };
+        await using var drv = FixedOnlyDriver(sw);
+        await drv.InitializeAsync("{}", CancellationToken.None);
+        // The bootstrap retries every 2 s, so the first failure is what has to trip it.
+        await WaitUntil(() => drv.GetHealth().State == DriverState.Degraded, TimeSpan.FromSeconds(6));
+        sw.Down = false;
+    }
+
+    /// <summary>
+    ///     A CNC that ANSWERS with a refusal is not a comms loss: the transport is fine, so the driver is not
+    ///     degraded (else the watchdog would reconnect-loop a production control).
+    /// </summary>
+    [Fact]
+    public async Task Cnc_refusal_of_the_dynamic_read_does_not_degrade()
+    {
+        var sw = new CncSwitch();
+        await using var drv = FixedOnlyDriver(sw);
+        await drv.InitializeAsync("{}", CancellationToken.None);
+        await WaitUntil(() => drv.GetDeviceState(Host)?.LastFixedPollUtc is not null);
+
+        sw.Refuse = true;
+        await Task.Delay(Stale * 3);
+        drv.GetHealth().State.ShouldBe(DriverState.Healthy);
+        sw.Refuse = false;
+    }
+
+    private static async Task WaitUntil(Func<bool> condition, TimeSpan? timeout = null)
+    {
+        var deadline = DateTime.UtcNow + (timeout ?? TimeSpan.FromSeconds(5));
+        while (!condition())
+        {
+            if (DateTime.UtcNow > deadline) throw new TimeoutException("condition not reached");
+            await Task.Delay(10);
+        }
+    }
+}