From 24a3cda56af313a18c5141b131aec1982cba2d26 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Sun, 26 Apr 2026 01:59:56 -0400 Subject: [PATCH] =?UTF-8?q?Auto:=20twincat-3.2=20=E2=80=94=20cycle-time=20?= =?UTF-8?q?/=20jitter=20/=20PLC-state=20diagnostics?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Closes #314 --- docs/Driver.TwinCAT.Cli.md | 29 +++ docs/drivers/TwinCAT-Test-Fixture.md | 35 +++ .../TwinCATDeviceDiagnostics.cs | 51 ++++ .../TwinCATDriver.cs | 198 +++++++++++++++- .../TwinCATDiagnosticsIntegrationTests.cs | 78 ++++++ .../TwinCatProject/README.md | 7 + .../FakeTwinCATClient.cs | 22 ++ .../TwinCATDeviceDiagnosticsTests.cs | 223 ++++++++++++++++++ 8 files changed, 642 insertions(+), 1 deletion(-) create mode 100644 src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDeviceDiagnostics.cs create mode 100644 tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCATDiagnosticsIntegrationTests.cs create mode 100644 tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATDeviceDiagnosticsTests.cs diff --git a/docs/Driver.TwinCAT.Cli.md b/docs/Driver.TwinCAT.Cli.md index 16caf52..69412aa 100644 --- a/docs/Driver.TwinCAT.Cli.md +++ b/docs/Driver.TwinCAT.Cli.md @@ -58,6 +58,35 @@ otopcua-twincat-cli probe -n 127.0.0.1.1.1 -s "TwinCAT_SystemInfoVarList._AppInf otopcua-twincat-cli probe -n 192.168.1.40.1.1 -s MAIN.bRunning --type Bool ``` +#### Health probe + +The OtOpcUa server's TwinCAT driver runs an internal probe loop (PR 3.2, issue #314) +that — alongside the cheap `ReadStateAsync` reachability check — samples four +well-known system symbols once per probe interval and surfaces the result through +the cross-driver `driver-diagnostics` RPC (added for Modbus, task #154). The same +symbols can be probed directly via the CLI for ad-hoc troubleshooting: + +```powershell +# Cycle time (UDINT, 100 ns ticks → ÷10000 for ms) +otopcua-twincat-cli probe -n 192.168.1.40.1.1 -s "TwinCAT_SystemInfoVarList._TaskInfo[1].CycleTime" --type UDInt + +# Last task execution wall-clock (UDINT, 100 ns ticks → ÷10000 for ms) +otopcua-twincat-cli probe -n 192.168.1.40.1.1 -s "TwinCAT_SystemInfoVarList._TaskInfo[1].LastExecTime" --type UDInt + +# Online-change count — increments on every accepted online change +otopcua-twincat-cli probe -n 192.168.1.40.1.1 -s "TwinCAT_SystemInfoVarList._AppInfo.OnlineChangeCnt" --type UDInt + +# Loaded PLC project name (STRING(80)) +otopcua-twincat-cli probe -n 192.168.1.40.1.1 -s "TwinCAT_SystemInfoVarList._AppInfo.AppName" --type String +``` + +Within the running OtOpcUa server these four signals land on +`DeviceState.LastDiagnostics` as a `TwinCATDeviceDiagnostics` record + are folded +into `DriverHealth.Diagnostics` keyed `TwinCAT.CycleTimeMs`, `TwinCAT.LastExecTimeMs`, +`TwinCAT.JitterMs` (computed `LastExecTimeMs - CycleTimeMs`), +`TwinCAT.OnlineChangeCnt`, and `TwinCAT.OnlineChangeIncrements`. See +`docs/drivers/TwinCAT-Test-Fixture.md §Diagnostics` for the full mapping. + ### `read` ```powershell diff --git a/docs/drivers/TwinCAT-Test-Fixture.md b/docs/drivers/TwinCAT-Test-Fixture.md index d6e9c37..82c59f8 100644 --- a/docs/drivers/TwinCAT-Test-Fixture.md +++ b/docs/drivers/TwinCAT-Test-Fixture.md @@ -198,6 +198,41 @@ on symbolic paths in PR 2.2 (the bulk path's per-call symbol resolution is already amortised across N tags; the perf delta vs. handle-batched bulk is marginal — tracked as a follow-up for the Phase-2 perf sweep). +## Diagnostics + +PR 3.2 (#314) augments the probe loop. On every successful tick (post `ReadStateAsync`) +the driver also reads four well-known system symbols off the AMS target and stashes +them on `DeviceState.LastDiagnostics` as a `TwinCATDeviceDiagnostics` record. The same +snapshot is folded into `DriverHealth.Diagnostics` so the cross-driver +`driver-diagnostics` RPC (added for Modbus, task #154) renders TwinCAT cycle-time / +jitter / online-change counters next to its peers without a per-driver special-case. + +| Symbol | Type | Diagnostic key | Notes | +| --- | --- | --- | --- | +| `TwinCAT_SystemInfoVarList._AppInfo.AppName` | `STRING(80)` | (record only) | Running PLC project name, e.g. `"Plc1"` | +| `TwinCAT_SystemInfoVarList._AppInfo.OnlineChangeCnt` | `UDINT` | `TwinCAT.OnlineChangeCnt` | Increments on every accepted online change; informational | +| `TwinCAT_SystemInfoVarList._TaskInfo[1].CycleTime` | `UDINT` (100 ns ticks) | `TwinCAT.CycleTimeMs` | Configured task period after `÷10000` ms conversion | +| `TwinCAT_SystemInfoVarList._TaskInfo[1].LastExecTime` | `UDINT` (100 ns ticks) | `TwinCAT.LastExecTimeMs` | Wall-clock duration of the last task tick | +| (computed) | `double` | `TwinCAT.JitterMs` | `LastExecTimeMs - CycleTimeMs`; positive = overrun | +| (computed) | `long` | `TwinCAT.OnlineChangeIncrements` | Cumulative deltas observed since the driver started; only emitted once non-zero | + +Each individual read is wrapped in best-effort try/catch. A runtime that doesn't +expose `_TaskInfo[1]` (older TwinCAT 2 builds, some soft-PLC implementations) still +produces a partial snapshot; the missing fields fall back to the previous tick's value +or the type default for the first probe tick. Wholesale failure of all four reads +leaves the previous snapshot in place and the next tick retries. + +Single-device deployments produce flat keys (`TwinCAT.CycleTimeMs`); multi-device +deployments prefix with the AMS host address (`TwinCAT..CycleTimeMs`) +so the readout is unambiguous when one driver instance owns multiple AMS targets. + +Wire-level coverage lives in +`TwinCATDiagnosticsIntegrationTests.Probe_loop_surfaces_cycle_time_and_online_change_count` +(asserts `CycleTimeMs > 0` + `OnlineChangeCnt >= 0` within one probe interval against a +reachable XAR runtime). Unit-level coverage of the dictionary shape, the per-symbol +try/catch, and the multi-device prefixing lives in `TwinCATDeviceDiagnosticsTests` — +the `FakeTwinCATClient.SetSystemSymbolValue` helper drives the surface deterministically. + ## Follow-up candidates 1. **XAR VM live-population** — scaffolding is in place (this PR); the diff --git a/src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDeviceDiagnostics.cs b/src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDeviceDiagnostics.cs new file mode 100644 index 0000000..32a3692 --- /dev/null +++ b/src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDeviceDiagnostics.cs @@ -0,0 +1,51 @@ +namespace ZB.MOM.WW.OtOpcUa.Driver.TwinCAT; + +/// +/// Per-device runtime diagnostics surfaced by the TwinCAT probe loop (PR 3.2 / issue #314). +/// Built by reading four well-known system symbols once per probe interval and stashed on +/// alongside the existing reachability +/// state. The driver also folds the latest snapshot into +/// so the cross-driver +/// driver-diagnostics RPC (introduced for Modbus task #154) can render TwinCAT +/// cycle-time / jitter / online-change counters next to its peers without a per-driver +/// special-case. +/// +/// +/// Value of TwinCAT_SystemInfoVarList._AppInfo.AppName. Identifies the running PLC +/// application (e.g. "Plc1") so an operator can tell which project is loaded against +/// the AMS target. +/// +/// +/// Value of TwinCAT_SystemInfoVarList._AppInfo.OnlineChangeCnt. Increments on every +/// accepted online-change. Diffing the value across probe ticks lets operators (and the +/// driver itself) react to runtime symbol-table churn — see the +/// TwinCAT.OnlineChangeCntDelta diagnostic key. +/// +/// +/// Value of TwinCAT_SystemInfoVarList._TaskInfo[1].CycleTime after the +/// 100 ns → ms conversion. Configured task period; constant under normal operation. +/// +/// +/// Value of TwinCAT_SystemInfoVarList._TaskInfo[1].LastExecTime after the +/// 100 ns → ms conversion. Wall-clock time the last task tick spent running. Compared to +/// to surface jitter / overrun. +/// +/// +/// LastExecTimeMs - CycleTimeMs. Positive values indicate the task overran its +/// configured cycle (potential cycle exceedance); negative / zero values are healthy. +/// +/// UTC instant the snapshot was captured. +/// +/// Each field is best-effort — the probe wraps individual symbol reads in try/catch so a +/// runtime that doesn't expose _TaskInfo[1] (older TwinCAT 2 builds) still produces a +/// partial snapshot with a non-null + . +/// Missing reads fall back to the previous snapshot's value (or the type default for the +/// first probe tick). +/// +public sealed record TwinCATDeviceDiagnostics( + string? AppName, + uint OnlineChangeCnt, + double CycleTimeMs, + double LastExecTimeMs, + double JitterMs, + DateTimeOffset UpdatedAt); diff --git a/src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs b/src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs index cca2848..3e0baed 100644 --- a/src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs +++ b/src/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT/TwinCATDriver.cs @@ -106,6 +106,15 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery internal DeviceState? GetDeviceState(string hostAddress) => _devices.TryGetValue(hostAddress, out var s) ? s : null; + /// + /// PR 3.2 / #314 — most recent snapshot for a + /// given AMS target, or null if the device hasn't completed a probe tick yet + /// (or the host address isn't configured on this driver). The aggregate view across + /// all devices is folded into on every probe tick. + /// + public TwinCATDeviceDiagnostics? GetDeviceDiagnostics(string hostAddress) => + _devices.TryGetValue(hostAddress, out var s) ? s.LastDiagnostics : null; + // ---- IReadable ---- /// @@ -522,14 +531,31 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery public IReadOnlyList GetHostStatuses() => [.. _devices.Values.Select(s => new HostConnectivityStatus(s.Options.HostAddress, s.HostState, s.HostStateChangedUtc))]; + // PR 3.2 / #314 — well-known TwinCAT system-symbol names. All four live under + // TwinCAT_SystemInfoVarList, exported by every TC2/TC3 PLC runtime alongside user + // symbols. Names are stable across runtime versions; the underlying type widths + // are also stable (UDINT for the time + count fields, STRING(80) for AppName). + internal const string SymOnlineChangeCnt = "TwinCAT_SystemInfoVarList._AppInfo.OnlineChangeCnt"; + internal const string SymAppName = "TwinCAT_SystemInfoVarList._AppInfo.AppName"; + internal const string SymCycleTime = "TwinCAT_SystemInfoVarList._TaskInfo[1].CycleTime"; + internal const string SymLastExecTime = "TwinCAT_SystemInfoVarList._TaskInfo[1].LastExecTime"; + + /// + /// Convert a TwinCAT 100 ns tick count to milliseconds. _TaskInfo[1].CycleTime + /// and LastExecTime both use the UDINT-sized 100 ns tick unit (1 tick = + /// 0.0001 ms), so the divisor is 10000. + /// + internal static double TicksToMilliseconds(uint ticks100ns) => ticks100ns / 10_000.0; + private async Task ProbeLoopAsync(DeviceState state, CancellationToken ct) { while (!ct.IsCancellationRequested) { var success = false; + ITwinCATClient? client = null; try { - var client = await EnsureConnectedAsync(state, ct).ConfigureAwait(false); + client = await EnsureConnectedAsync(state, ct).ConfigureAwait(false); success = await client.ProbeAsync(ct).ConfigureAwait(false); } catch (OperationCanceledException) when (ct.IsCancellationRequested) { break; } @@ -539,6 +565,24 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery // + cleared the client, so next tick will reconnect. } + // PR 3.2 / #314 — only sample the four system symbols when the basic probe + // succeeded. Reading them on a stopped runtime would just generate noise + + // would race with the reconnect path. + if (success && client is not null) + { + try + { + await SampleDeviceDiagnosticsAsync(state, client, ct).ConfigureAwait(false); + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) { break; } + catch + { + // Diagnostics sampling is best-effort. A wholesale failure (target dropped + // mid-probe, transient AMS error) leaves the previous snapshot in place; + // the next tick retries. + } + } + TransitionDeviceState(state, success ? HostState.Running : HostState.Stopped); try { await Task.Delay(_options.Probe.Interval, ct).ConfigureAwait(false); } @@ -546,6 +590,149 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery } } + /// + /// Read the four well-known TwinCAT system symbols (, + /// , , + /// ) and stash the resulting + /// snapshot on + /// . Each read is wrapped individually so a + /// runtime that doesn't expose _TaskInfo[1] (older TwinCAT 2 builds) still + /// produces a partial snapshot rather than failing the whole probe tick. + /// + internal async Task SampleDeviceDiagnosticsAsync( + DeviceState state, ITwinCATClient client, CancellationToken ct) + { + var prev = state.LastDiagnostics; + var appName = prev?.AppName; + var onlineChangeCnt = prev?.OnlineChangeCnt ?? 0u; + var cycleTimeMs = prev?.CycleTimeMs ?? 0.0; + var lastExecMs = prev?.LastExecTimeMs ?? 0.0; + + // AppName — STRING(80) on the wire. Fixed-size; AdsClient marshals as System.String. + try + { + var (rawAppName, statusName) = await client.ReadValueAsync( + SymAppName, TwinCATDataType.String, bitIndex: null, arrayDimensions: null, ct) + .ConfigureAwait(false); + if (statusName == TwinCATStatusMapper.Good && rawAppName is string s) + appName = s; + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) { throw; } + catch + { + // Older TC2 / soft-PLC builds may not surface AppName via the system var list — + // leave the previous snapshot's value in place. + } + + // OnlineChangeCnt — UDINT. + try + { + var (rawCnt, statusCnt) = await client.ReadValueAsync( + SymOnlineChangeCnt, TwinCATDataType.UDInt, bitIndex: null, arrayDimensions: null, ct) + .ConfigureAwait(false); + if (statusCnt == TwinCATStatusMapper.Good && rawCnt is not null) + onlineChangeCnt = Convert.ToUInt32(rawCnt); + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) { throw; } + catch { /* skip without failing the probe */ } + + // CycleTime — UDINT, 100 ns ticks. + try + { + var (rawCycle, statusCycle) = await client.ReadValueAsync( + SymCycleTime, TwinCATDataType.UDInt, bitIndex: null, arrayDimensions: null, ct) + .ConfigureAwait(false); + if (statusCycle == TwinCATStatusMapper.Good && rawCycle is not null) + cycleTimeMs = TicksToMilliseconds(Convert.ToUInt32(rawCycle)); + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) { throw; } + catch { /* skip without failing the probe */ } + + // LastExecTime — UDINT, 100 ns ticks. + try + { + var (rawExec, statusExec) = await client.ReadValueAsync( + SymLastExecTime, TwinCATDataType.UDInt, bitIndex: null, arrayDimensions: null, ct) + .ConfigureAwait(false); + if (statusExec == TwinCATStatusMapper.Good && rawExec is not null) + lastExecMs = TicksToMilliseconds(Convert.ToUInt32(rawExec)); + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) { throw; } + catch { /* skip without failing the probe */ } + + var jitterMs = lastExecMs - cycleTimeMs; + var snapshot = new TwinCATDeviceDiagnostics( + appName, onlineChangeCnt, cycleTimeMs, lastExecMs, jitterMs, DateTimeOffset.UtcNow); + + // OnlineChangeCnt increment — surface the delta on _health.Diagnostics so the + // cross-driver RPC + the Admin UI can highlight runtime symbol-table churn. + // The actual cache invalidation is handled separately by the AdsSymbolVersionChanged + // listener (PR 2.3); this is purely informational. + if (prev is not null && snapshot.OnlineChangeCnt > prev.OnlineChangeCnt) + Interlocked.Add(ref _onlineChangeIncrementsObserved, + (long)(snapshot.OnlineChangeCnt - prev.OnlineChangeCnt)); + + state.LastDiagnostics = snapshot; + RebuildHealthDiagnostics(); + } + + // Counter for OnlineChangeCnt increments observed across the lifetime of the driver + // instance, summed across every device. Surfaced as TwinCAT.OnlineChangeIncrements + // in DriverHealth.Diagnostics so operators can see "how many online changes have we + // observed since process start" without having to diff successive _TaskInfo snapshots. + private long _onlineChangeIncrementsObserved; + + /// Test-only — count of OnlineChangeCnt increments folded into the diagnostic dictionary. + internal long OnlineChangeIncrementsObserved => Interlocked.Read(ref _onlineChangeIncrementsObserved); + + /// + /// Refresh with a freshly-built diagnostics dictionary that + /// aggregates the snapshots across every + /// device. Keys follow the cross-driver + /// "<DriverType>.<Counter>" convention so the driver-diagnostics + /// RPC can render them alongside Modbus / S7 / OPC UA Client metrics. Single-device + /// deployments produce flat keys (TwinCAT.CycleTimeMs); multi-device deployments + /// prefix the host address (TwinCAT.<hostAddress>.CycleTimeMs) so the + /// readout is unambiguous when multiple AMS targets share one driver instance. + /// + internal void RebuildHealthDiagnostics() + { + var diags = BuildAggregateDiagnostics(); + var current = _health; + _health = new DriverHealth(current.State, current.LastSuccessfulRead, current.LastError, diags); + } + + /// + /// Snapshot the per-device into the cross-driver + /// dictionary shape exposes. Empty when no probe + /// has completed yet — the caller (Admin UI / driver-diagnostics RPC) is expected to + /// handle the empty case the same way it does for any other driver pre-connect. + /// + internal IReadOnlyDictionary BuildAggregateDiagnostics() + { + var dict = new Dictionary(StringComparer.Ordinal); + var multiDevice = _devices.Count > 1; + + foreach (var (hostAddress, state) in _devices) + { + if (state.LastDiagnostics is not { } snap) continue; + var prefix = multiDevice + ? $"TwinCAT.{hostAddress}." + : "TwinCAT."; + dict[prefix + "OnlineChangeCnt"] = snap.OnlineChangeCnt; + dict[prefix + "CycleTimeMs"] = snap.CycleTimeMs; + dict[prefix + "LastExecTimeMs"] = snap.LastExecTimeMs; + dict[prefix + "JitterMs"] = snap.JitterMs; + dict[prefix + "DiagnosticsUpdatedAtTicks"] = snap.UpdatedAt.UtcTicks; + } + + var increments = Interlocked.Read(ref _onlineChangeIncrementsObserved); + if (increments > 0) + dict["TwinCAT.OnlineChangeIncrements"] = increments; + + return dict; + } + private void TransitionDeviceState(DeviceState state, HostState newState) { HostState old; @@ -620,6 +807,15 @@ public sealed class TwinCATDriver : IDriver, IReadable, IWritable, ITagDiscovery public DateTime HostStateChangedUtc { get; set; } = DateTime.UtcNow; public CancellationTokenSource? ProbeCts { get; set; } + /// + /// PR 3.2 / #314 — most recent sample taken + /// by the probe loop, or null before the first successful probe tick. Single + /// writer (the per-device probe task) + many readers ( + /// , the diagnostic-dictionary + /// rebuild). The record is immutable so a torn-read on assignment is impossible. + /// + public TwinCATDeviceDiagnostics? LastDiagnostics { get; set; } + public void DisposeClient() { Client?.Dispose(); diff --git a/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCATDiagnosticsIntegrationTests.cs b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCATDiagnosticsIntegrationTests.cs new file mode 100644 index 0000000..692e629 --- /dev/null +++ b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCATDiagnosticsIntegrationTests.cs @@ -0,0 +1,78 @@ +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Driver.TwinCAT; + +namespace ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests; + +/// +/// PR 3.2 / issue #314 — wire-level coverage for the cycle-time / jitter / online-change +/// diagnostics surfaced through the probe loop. Skipped via +/// when the XAR VM isn't reachable. The four well-known system symbols +/// (TwinCAT_SystemInfoVarList._AppInfo.OnlineChangeCnt, _AppInfo.AppName, +/// _TaskInfo[1].CycleTime, _TaskInfo[1].LastExecTime) are always exported by +/// a live TC3 PLC runtime — no extra fixture state required beyond the existing +/// GVL_Fixture / MAIN setup documented in TwinCatProject/README.md. +/// +[Collection("TwinCATXar")] +[Trait("Category", "Integration")] +[Trait("Simulator", "TwinCAT-XAR")] +public sealed class TwinCATDiagnosticsIntegrationTests(TwinCATXarFixture sim) +{ + [TwinCATFact] + public async Task Probe_loop_surfaces_cycle_time_and_online_change_count() + { + if (sim.SkipReason is not null) Assert.Skip(sim.SkipReason); + + // Probe interval kept tight (250 ms) so the test doesn't have to wait the default 5 s + // between probe ticks. The four system symbols are scalar UDINTs / a STRING(80), so + // the diagnostics sample completes well within the 250 ms budget on any healthy + // runtime. + var options = new TwinCATDriverOptions + { + Devices = [ + new TwinCATDeviceOptions( + HostAddress: $"ads://{sim.TargetNetId}:{sim.AmsPort}", + DeviceName: "XAR-VM"), + ], + // No Tags — diagnostics doesn't need any user-declared symbols. + Tags = [], + UseNativeNotifications = false, + Timeout = TimeSpan.FromSeconds(5), + Probe = new TwinCATProbeOptions + { + Enabled = true, + Interval = TimeSpan.FromMilliseconds(250), + }, + }; + + await using var drv = new TwinCATDriver(options, driverInstanceId: "tc3-diag-probe"); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + + // Wait up to 5 s for the probe loop to fire at least once + populate the snapshot. + // 250 ms cycle × 20 attempts ≈ 5 s budget — generous enough for AMS handshake on a + // freshly-restarted runtime. + var hostAddress = $"ads://{sim.TargetNetId}:{sim.AmsPort}"; + TwinCATDeviceDiagnostics? snap = null; + for (var i = 0; i < 20 && snap is null; i++) + { + await Task.Delay(250, TestContext.Current.CancellationToken); + snap = drv.GetDeviceDiagnostics(hostAddress); + } + + snap.ShouldNotBeNull( + "probe loop must populate TwinCATDeviceDiagnostics within ~5 s on a reachable XAR runtime"); + snap.CycleTimeMs.ShouldBeGreaterThan(0, + "TwinCAT_SystemInfoVarList._TaskInfo[1].CycleTime is non-zero on every running PLC task"); + snap.OnlineChangeCnt.ShouldBeGreaterThanOrEqualTo(0u, + "OnlineChangeCnt is a UDINT counter — non-negative by type, present on every TC3 runtime"); + // AppName is best-effort but on a project-loaded runtime it should be non-empty. + snap.AppName.ShouldNotBeNull("running PLC project always reports an AppName"); + + // The cross-driver DriverHealth.Diagnostics dictionary should also reflect the same + // values so the driver-diagnostics RPC has a consistent surface. + var dict = drv.GetHealth().DiagnosticsOrEmpty; + dict["TwinCAT.CycleTimeMs"].ShouldBe(snap.CycleTimeMs); + dict["TwinCAT.OnlineChangeCnt"].ShouldBe(snap.OnlineChangeCnt); + } +} diff --git a/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCatProject/README.md b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCatProject/README.md index b5ab92c..a85f2ca 100644 --- a/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCatProject/README.md +++ b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.IntegrationTests/TwinCatProject/README.md @@ -71,6 +71,13 @@ GVL_Fixture.nCounter := GVL_Fixture.nCounter + 1; - `PlcTask` — cyclic, 10 ms interval, priority 20 - Assigned to `MAIN` +> **Note (PR 3.2 / #314)**: the probe loop also reads the four +> `TwinCAT_SystemInfoVarList` system symbols (`_AppInfo.AppName`, +> `_AppInfo.OnlineChangeCnt`, `_TaskInfo[1].CycleTime`, `_TaskInfo[1].LastExecTime`) +> per tick — they're exported by every TC3 PLC runtime, so no extra fixture state +> is required. `TwinCATDiagnosticsIntegrationTests` asserts they surface on +> `DriverHealth.Diagnostics`. + > **Note (PR 3.1 / #313)**: `GVL_Fixture.nCounter` doubles as the > coalescing-test driver for `TwinCATMaxDelayTests`. The 10 ms cycle + > per-cycle increment in `MAIN` means a no-coalescing subscriber sees ~100 diff --git a/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/FakeTwinCATClient.cs b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/FakeTwinCATClient.cs index fb49e75..2091500 100644 --- a/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/FakeTwinCATClient.cs +++ b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/FakeTwinCATClient.cs @@ -14,6 +14,28 @@ internal class FakeTwinCATClient : ITwinCATClient public bool ThrowOnProbe { get; set; } public Exception? Exception { get; set; } public Dictionary Values { get; } = new(StringComparer.OrdinalIgnoreCase); + + /// + /// Convenience seed for the well-known TwinCAT system symbols + /// (TwinCAT_SystemInfoVarList._AppInfo.OnlineChangeCnt, + /// _AppInfo.AppName, _TaskInfo[1].CycleTime, + /// _TaskInfo[1].LastExecTime) used by PR 3.2's probe-loop diagnostics. + /// Internally just writes to ; provided as a named helper so tests + /// read clearly + so future schema changes (e.g. wrapping the system-symbol surface in + /// a typed snapshot) have one place to update. + /// + public void SetSystemSymbolValue(string name, object? value) => Values[name] = value; + + /// + /// Force the next read of to fail with the supplied + /// . Subsequent reads after that fall back to the default + /// Good behaviour. Used by the PR 3.2 probe-loop tests to simulate a runtime that + /// doesn't expose _TaskInfo[1]. + /// + public void FailNextReadOf(string symbolPath, uint status = TwinCATStatusMapper.BadCommunicationError) + { + ReadStatuses[symbolPath] = status; + } public Dictionary ReadStatuses { get; } = new(StringComparer.OrdinalIgnoreCase); public Dictionary WriteStatuses { get; } = new(StringComparer.OrdinalIgnoreCase); public List<(string symbol, TwinCATDataType type, int? bit, object? value)> WriteLog { get; } = new(); diff --git a/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATDeviceDiagnosticsTests.cs b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATDeviceDiagnosticsTests.cs new file mode 100644 index 0000000..edd8cff --- /dev/null +++ b/tests/ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests/TwinCATDeviceDiagnosticsTests.cs @@ -0,0 +1,223 @@ +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; +using ZB.MOM.WW.OtOpcUa.Driver.TwinCAT; + +namespace ZB.MOM.WW.OtOpcUa.Driver.TwinCAT.Tests; + +/// +/// PR 3.2 / issue #314 — unit-level coverage for the cycle-time / jitter / online-change +/// diagnostics surfaced by the probe loop. The probe-loop scheduler is hard to drive +/// deterministically (it has its own ), so these tests invoke the +/// internal directly with seeded +/// values on the . Wire-level coverage lives in the +/// integration suite (TwinCATDiagnosticsIntegrationTests). +/// +[Trait("Category", "Unit")] +public sealed class TwinCATDeviceDiagnosticsTests +{ + private const string Host = "ads://5.23.91.23.1.1:851"; + + [Fact] + public async Task SampleDeviceDiagnosticsAsync_populates_LastDiagnostics_with_seeded_values() + { + var fake = new FakeTwinCATClient(); + // Seed: AppName "Plc1", OnlineChangeCnt 7, CycleTime 100_000 ticks (10 ms), + // LastExecTime 35_000 ticks (3.5 ms) → JitterMs = 3.5 - 10.0 = -6.5 (healthy). + fake.SetSystemSymbolValue(TwinCATDriver.SymAppName, "Plc1"); + fake.SetSystemSymbolValue(TwinCATDriver.SymOnlineChangeCnt, 7u); + fake.SetSystemSymbolValue(TwinCATDriver.SymCycleTime, 100_000u); + fake.SetSystemSymbolValue(TwinCATDriver.SymLastExecTime, 35_000u); + + await using var drv = BuildDriverWithClient(fake); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + + var state = drv.GetDeviceState(Host)!; + await fake.ConnectAsync(state.ParsedAddress, TimeSpan.FromSeconds(1), TestContext.Current.CancellationToken); + await drv.SampleDeviceDiagnosticsAsync(state, fake, TestContext.Current.CancellationToken); + + var diags = drv.GetDeviceDiagnostics(Host).ShouldNotBeNull(); + diags.AppName.ShouldBe("Plc1"); + diags.OnlineChangeCnt.ShouldBe(7u); + diags.CycleTimeMs.ShouldBe(10.0, tolerance: 0.001); + diags.LastExecTimeMs.ShouldBe(3.5, tolerance: 0.001); + diags.JitterMs.ShouldBe(-6.5, tolerance: 0.001); + } + + [Fact] + public async Task SampleDeviceDiagnosticsAsync_skips_failing_TaskInfo_read_without_failing_probe() + { + // Older TC2 / soft-PLC builds may not surface _TaskInfo[1]; the probe loop should still + // produce a partial snapshot rather than failing the whole tick. + var fake = new FakeTwinCATClient(); + fake.SetSystemSymbolValue(TwinCATDriver.SymAppName, "Plc1"); + fake.SetSystemSymbolValue(TwinCATDriver.SymOnlineChangeCnt, 3u); + // CycleTime + LastExecTime not seeded; force them to surface as Bad so the probe path + // exercises the per-symbol try/catch. + fake.FailNextReadOf(TwinCATDriver.SymCycleTime); + fake.FailNextReadOf(TwinCATDriver.SymLastExecTime); + + await using var drv = BuildDriverWithClient(fake); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + + var state = drv.GetDeviceState(Host)!; + await fake.ConnectAsync(state.ParsedAddress, TimeSpan.FromSeconds(1), TestContext.Current.CancellationToken); + await drv.SampleDeviceDiagnosticsAsync(state, fake, TestContext.Current.CancellationToken); + + var diags = drv.GetDeviceDiagnostics(Host).ShouldNotBeNull(); + diags.AppName.ShouldBe("Plc1"); + diags.OnlineChangeCnt.ShouldBe(3u); + // Failed reads leave the previous-tick value (or 0 on the first tick) — both are + // acceptable since the API guarantees the field is best-effort. + diags.CycleTimeMs.ShouldBe(0.0); + diags.LastExecTimeMs.ShouldBe(0.0); + } + + [Fact] + public async Task SampleDeviceDiagnosticsAsync_OnlineChangeCnt_increment_surfaces_in_diagnostics_dictionary() + { + var fake = new FakeTwinCATClient(); + fake.SetSystemSymbolValue(TwinCATDriver.SymAppName, "Plc1"); + fake.SetSystemSymbolValue(TwinCATDriver.SymOnlineChangeCnt, 2u); + fake.SetSystemSymbolValue(TwinCATDriver.SymCycleTime, 100_000u); + fake.SetSystemSymbolValue(TwinCATDriver.SymLastExecTime, 50_000u); + + await using var drv = BuildDriverWithClient(fake); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + + var state = drv.GetDeviceState(Host)!; + await fake.ConnectAsync(state.ParsedAddress, TimeSpan.FromSeconds(1), TestContext.Current.CancellationToken); + await drv.SampleDeviceDiagnosticsAsync(state, fake, TestContext.Current.CancellationToken); + drv.OnlineChangeIncrementsObserved.ShouldBe(0, + "first tick has no prior snapshot to diff against"); + + // Operator reloads the project; runtime increments OnlineChangeCnt by 3. + fake.SetSystemSymbolValue(TwinCATDriver.SymOnlineChangeCnt, 5u); + await drv.SampleDeviceDiagnosticsAsync(state, fake, TestContext.Current.CancellationToken); + + drv.OnlineChangeIncrementsObserved.ShouldBe(3); + + var diagsAfter = drv.GetDeviceDiagnostics(Host).ShouldNotBeNull(); + diagsAfter.OnlineChangeCnt.ShouldBe(5u); + + // Aggregate dict on _health surfaces both the latest snapshot + the cumulative + // increment counter so the cross-driver RPC can render either view. + var health = drv.GetHealth(); + var dict = health.DiagnosticsOrEmpty; + dict["TwinCAT.OnlineChangeCnt"].ShouldBe(5.0); + dict["TwinCAT.OnlineChangeIncrements"].ShouldBe(3.0); + } + + [Fact] + public async Task SampleDeviceDiagnosticsAsync_folds_snapshot_into_DriverHealth_diagnostics() + { + var fake = new FakeTwinCATClient(); + fake.SetSystemSymbolValue(TwinCATDriver.SymAppName, "Plc1"); + fake.SetSystemSymbolValue(TwinCATDriver.SymOnlineChangeCnt, 11u); + // 2 ms cycle / 5 ms exec → 3 ms jitter (overrunning). + fake.SetSystemSymbolValue(TwinCATDriver.SymCycleTime, 20_000u); + fake.SetSystemSymbolValue(TwinCATDriver.SymLastExecTime, 50_000u); + + await using var drv = BuildDriverWithClient(fake); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + + var state = drv.GetDeviceState(Host)!; + await fake.ConnectAsync(state.ParsedAddress, TimeSpan.FromSeconds(1), TestContext.Current.CancellationToken); + await drv.SampleDeviceDiagnosticsAsync(state, fake, TestContext.Current.CancellationToken); + + var dict = drv.GetHealth().DiagnosticsOrEmpty; + dict["TwinCAT.OnlineChangeCnt"].ShouldBe(11.0); + dict["TwinCAT.CycleTimeMs"].ShouldBe(2.0, tolerance: 0.001); + dict["TwinCAT.LastExecTimeMs"].ShouldBe(5.0, tolerance: 0.001); + dict["TwinCAT.JitterMs"].ShouldBe(3.0, tolerance: 0.001); + dict.ShouldContainKey("TwinCAT.DiagnosticsUpdatedAtTicks"); + } + + [Fact] + public async Task SampleDeviceDiagnosticsAsync_multiple_devices_get_host_prefixed_keys() + { + const string Host2 = "ads://10.0.0.1.1.1:852"; + var fake1 = new FakeTwinCATClient(); + fake1.SetSystemSymbolValue(TwinCATDriver.SymAppName, "Plc1"); + fake1.SetSystemSymbolValue(TwinCATDriver.SymOnlineChangeCnt, 1u); + fake1.SetSystemSymbolValue(TwinCATDriver.SymCycleTime, 10_000u); + fake1.SetSystemSymbolValue(TwinCATDriver.SymLastExecTime, 5_000u); + + var fake2 = new FakeTwinCATClient(); + fake2.SetSystemSymbolValue(TwinCATDriver.SymAppName, "Plc2"); + fake2.SetSystemSymbolValue(TwinCATDriver.SymOnlineChangeCnt, 9u); + fake2.SetSystemSymbolValue(TwinCATDriver.SymCycleTime, 100_000u); + fake2.SetSystemSymbolValue(TwinCATDriver.SymLastExecTime, 80_000u); + + var queue = new Queue([fake1, fake2]); + var factory = new FakeTwinCATClientFactory { Customise = () => queue.Dequeue() }; + await using var drv = new TwinCATDriver(new TwinCATDriverOptions + { + Devices = [ + new TwinCATDeviceOptions(Host), + new TwinCATDeviceOptions(Host2), + ], + Probe = new TwinCATProbeOptions { Enabled = false }, + }, "drv-multi", factory); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + + var s1 = drv.GetDeviceState(Host)!; + var s2 = drv.GetDeviceState(Host2)!; + await fake1.ConnectAsync(s1.ParsedAddress, TimeSpan.FromSeconds(1), TestContext.Current.CancellationToken); + await fake2.ConnectAsync(s2.ParsedAddress, TimeSpan.FromSeconds(1), TestContext.Current.CancellationToken); + + await drv.SampleDeviceDiagnosticsAsync(s1, fake1, TestContext.Current.CancellationToken); + await drv.SampleDeviceDiagnosticsAsync(s2, fake2, TestContext.Current.CancellationToken); + + var dict = drv.GetHealth().DiagnosticsOrEmpty; + // Multi-device: keys are prefixed with the host address so the cross-driver RPC + // can disambiguate. + dict[$"TwinCAT.{Host}.OnlineChangeCnt"].ShouldBe(1.0); + dict[$"TwinCAT.{Host2}.OnlineChangeCnt"].ShouldBe(9.0); + dict[$"TwinCAT.{Host}.CycleTimeMs"].ShouldBe(1.0, tolerance: 0.001); + dict[$"TwinCAT.{Host2}.CycleTimeMs"].ShouldBe(10.0, tolerance: 0.001); + } + + [Fact] + public void TicksToMilliseconds_converts_100ns_units() + { + TwinCATDriver.TicksToMilliseconds(0u).ShouldBe(0.0); + TwinCATDriver.TicksToMilliseconds(10_000u).ShouldBe(1.0, tolerance: 0.001); + TwinCATDriver.TicksToMilliseconds(100_000u).ShouldBe(10.0, tolerance: 0.001); + TwinCATDriver.TicksToMilliseconds(uint.MaxValue).ShouldBe(429_496.7295, tolerance: 0.001); + } + + [Fact] + public async Task GetDeviceDiagnostics_returns_null_before_first_probe() + { + await using var drv = BuildDriverWithClient(new FakeTwinCATClient()); + await drv.InitializeAsync("{}", TestContext.Current.CancellationToken); + drv.GetDeviceDiagnostics(Host).ShouldBeNull(); + drv.GetDeviceDiagnostics("ads://does.not.exist:851").ShouldBeNull(); + } + + /// + /// Build a driver wired to the supplied . Inserts the fake into a + /// factory's Customise hook so the first + /// call hands back the seeded fake. Caller drives + /// directly. + /// + private static TwinCATDriver BuildDriverWithClient(FakeTwinCATClient fake) + { + var dispensed = false; + var factory = new FakeTwinCATClientFactory + { + Customise = () => + { + if (dispensed) return new FakeTwinCATClient(); + dispensed = true; + return fake; + }, + }; + return new TwinCATDriver(new TwinCATDriverOptions + { + Devices = [new TwinCATDeviceOptions(Host)], + Probe = new TwinCATProbeOptions { Enabled = false }, + }, "drv-diag", factory); + } +}