From a0b635f67383e5c21532deeede1633082980cb34 Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Thu, 22 Oct 2026 15:33:38 -0400 Subject: [PATCH] fix(s7): probe gate contention is no verdict; Test Connect honours timeoutMs (R07:H7) - The background probe reported the host Stopped whenever a read pass held _gate past the probe deadline: contention is the connection being used, not lost. A contended tick now gives no verdict (counted for tests); a real probe failure still reports Stopped. A tick that races a teardown no longer reopens a connection on an uninitialised driver. - S7DriverProbe deserialised S7DriverOptions directly, whose Timeout is a TimeSpan no config names, so "timeoutMs" was ignored and every handshake waited the whole Test Connect budget. The handshake and test read are now bounded by timeoutMs, capped by the caller's timeout. Refs #742 Claude-Session: https://claude.ai/code/session_01Ub9hGmYLQvn9XETzw7CMsT --- docs/drivers/S7.md | 5 +- .../ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs | 112 ++++++++++------ .../S7DriverProbe.cs | 39 +++++- .../S7ProbeContentionAndTimeoutTests.cs | 121 ++++++++++++++++++ 4 files changed, 233 insertions(+), 44 deletions(-) create mode 100644 tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7ProbeContentionAndTimeoutTests.cs diff --git a/docs/drivers/S7.md b/docs/drivers/S7.md index 207d26b1..889d08be 100644 --- a/docs/drivers/S7.md +++ b/docs/drivers/S7.md @@ -88,6 +88,9 @@ After the handshake, Test Connect reads 2 bytes from `MB0`. A CPU with PUT/GET d default) completes the handshake but denies every read, so the probe fails with an actionable "enable PUT/GET communication" message instead of a false green tick. A CPU that merely rejects that address (no `MB0`) still passes — the connection is fine; any other read fault fails the probe with its message. +Both are recognised in the bare-`Exception` shape S7.Net's read path really raises. The handshake and +test read are bounded by the config's `timeoutMs` (the driver's own per-operation timeout), capped by the +Test Connect timeout — before R07:H7 the config value was ignored. ## Address forms @@ -286,7 +289,7 @@ AdminUI `/hosts` page (Gitea #640). See `docs/Telemetry.md` ("Driver diagnostics | `IWritable` | `WriteAsync` → `S7.Net.Plc.WriteAsync` | Read-only tags (`Writable=false`) return `BadNotWritable` | | `ITagDiscovery` | `DiscoverAsync` | Emits a flat `S7/` folder of the configured tags — no live browse | | `ISubscribable` | per-tag poll loop with capped exponential backoff | S7 has no push model; floor is 100 ms (the CPU services the comms mailbox once per scan) | -| `IHostConnectivityProbe` | periodic `S7.Net.Plc.ReadStatusAsync` (CPU-status PDU) | `host:port` host key; `Running`/`Stopped` transitions raise `OnHostStatusChanged` | +| `IHostConnectivityProbe` | periodic `S7.Net.Plc.ReadStatusAsync` (CPU-status PDU) | `host:port` host key; `Running`/`Stopped` transitions raise `OnHostStatusChanged`. A tick that finds the gate held past the probe deadline (a long read pass) gives **no verdict** — it no longer reports `Stopped` for a connection that is busy, not lost (R07:H7) | ### Single-connection policy diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs index 9b0ce86b..9f0e98ae 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7Driver.cs @@ -2792,66 +2792,96 @@ public sealed class S7Driver { while (!ct.IsCancellationRequested) { - var success = false; + // Running / Stopped, or null for "no verdict this tick" — which leaves the host state alone. + HostState? verdict = null; try { // Probe via S7.Net's low-cost GetCpuStatus — returns the CPU state (Run/Stop) // and is intentionally light on the comms mailbox. Single-word Plc.ReadAsync // would also work but GetCpuStatus doubles as a "PLC actually up" check. - using var gateCts = CancellationTokenSource.CreateLinkedTokenSource(ct); - gateCts.CancelAfter(_options.Probe.Timeout); - - await _gate.WaitAsync(gateCts.Token).ConfigureAwait(false); - try + // + // Gate CONTENTION is not a verdict (R07:H7): a read pass or write batch holding the + // gate past the probe deadline is the connection being USED, and that pass reports + // its own outcome through health. Reporting the host Stopped for it flapped /hosts on + // every long pass against a perfectly healthy PLC. + if (!await _gate.WaitAsync(_options.Probe.Timeout, ct).ConfigureAwait(false)) + { + Interlocked.Increment(ref _probeGateContentions); + } + else { try { - // EnsureConnectedAsync doubles as the reconnect backstop: if a read/write - // marked the handle dead (or the socket dropped between ticks), the probe - // reopens it here so recovery doesn't wait for the next data call. - // It runs on the LOOP token, not the (shorter) probe deadline: the connect is bounded by - // _options.Timeout inside, and a timeout there must count as a failure so the - // backoff window opens — cutting it with the probe deadline looked like a caller cancel, - // recorded nothing, and let a black-holed host cost a connect attempt every probe tick. - var plc = await EnsureConnectedAsync(ct).ConfigureAwait(false); - // The probe deadline bounds only the CPU-status round trip. - using var probeCts = CancellationTokenSource.CreateLinkedTokenSource(ct); - probeCts.CancelAfter(_options.Probe.Timeout); - await plc.ReadStatusAsync(probeCts.Token).ConfigureAwait(false); - success = true; - } - catch (OperationCanceledException) when (ct.IsCancellationRequested) - { - // Loop teardown — rethrow to the outer filter (after finally releases the gate). - throw; - } - catch (OperationCanceledException) - { - // Probe deadline fired mid-PDU: the CPU-status response may still be in - // flight, so the handle can't be reused (half-read ⇒ desync). We hold _gate - // here, keeping _plcDead gate-guarded. - _plcDead = true; - } - catch (Exception ex) - { - // Classify + mark while holding _gate so a wire-dead/desynced - // handle whose TcpClient still claims Connected is reopened by the NEXT - // tick's EnsureConnectedAsync instead of being re-probed forever. - MarkConnectionDeadIfFatal(ex); + // A tick that raced a teardown / re-initialize has nothing to probe and must + // not reopen a connection on a driver that is not initialized. + if (_initialized) + verdict = await ProbeOnceAsync(ct).ConfigureAwait(false); } + finally { _gate.Release(); } } - finally { _gate.Release(); } } catch (OperationCanceledException) when (ct.IsCancellationRequested) { return; } - catch { /* gate-wait timeout / other — treated as Stopped below (gate contention is not a connection fault) */ } + catch { verdict = HostState.Stopped; /* any other probe fault */ } - TransitionTo(success ? HostState.Running : HostState.Stopped); + if (verdict is { } state) TransitionTo(state); try { await Task.Delay(_options.Probe.Interval, ct).ConfigureAwait(false); } catch (OperationCanceledException) { return; } } } + /// + /// One probe round trip. Caller holds . Returns the verdict; rethrows only + /// loop teardown. + /// + /// The probe loop's token. + /// or . + private async Task ProbeOnceAsync(CancellationToken ct) + { + try + { + // EnsureConnectedAsync doubles as the reconnect backstop: if a read/write marked the handle + // dead (or the socket dropped between ticks), the probe reopens it here so recovery doesn't + // wait for the next data call. It runs on the LOOP token, not the (shorter) probe deadline: + // the connect is bounded by _options.Timeout inside, and a timeout there must count as a + // failure so the backoff window opens — cutting it with the probe deadline looked like a + // caller cancel, recorded nothing, and let a black-holed host cost a connect attempt every + // probe tick. + var plc = await EnsureConnectedAsync(ct).ConfigureAwait(false); + // The probe deadline bounds only the CPU-status round trip. + using var probeCts = CancellationTokenSource.CreateLinkedTokenSource(ct); + probeCts.CancelAfter(_options.Probe.Timeout); + await plc.ReadStatusAsync(probeCts.Token).ConfigureAwait(false); + return HostState.Running; + } + catch (OperationCanceledException) when (ct.IsCancellationRequested) + { + throw; // loop teardown — the caller's finally releases the gate + } + catch (OperationCanceledException) + { + // Probe deadline fired mid-PDU: the CPU-status response may still be in flight, so the + // handle can't be reused (half-read ⇒ desync). The caller holds _gate, keeping _plcDead + // gate-guarded. + _plcDead = true; + return HostState.Stopped; + } + catch (Exception ex) + { + // Classify + mark while holding _gate so a wire-dead/desynced handle whose TcpClient still + // claims Connected is reopened by the NEXT tick's EnsureConnectedAsync instead of being + // re-probed forever. + MarkConnectionDeadIfFatal(ex); + return HostState.Stopped; + } + } + + /// Probe ticks that found the gate held past the probe deadline and gave no verdict. + private int _probeGateContentions; + + /// Count of probe ticks skipped for gate contention. Internal so a test can wait on it. + internal int ProbeGateContentions => Volatile.Read(ref _probeGateContentions); + private void TransitionTo(HostState newState) { HostState old; diff --git a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7DriverProbe.cs b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7DriverProbe.cs index 13925989..ad53b8b7 100644 --- a/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7DriverProbe.cs +++ b/src/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7/S7DriverProbe.cs @@ -42,6 +42,14 @@ public sealed class S7DriverProbe : IDriverProbe if (string.IsNullOrWhiteSpace(host) || port <= 0) return new(false, "Config has no host/port to probe.", null); + // The S7 handshake + test read are bounded by the driver's own per-operation timeout + // (config "timeoutMs", what the deployed driver will wait), capped by the caller's overall + // Test Connect timeout. The options type carries it as a TimeSpan the JSON never names, so it + // used to be ignored and every handshake waited the full Test Connect timeout (R07:H7). + var opTimeout = ReadTimeoutMs(configJson) is { } ms && TimeSpan.FromMilliseconds(ms) < timeout + ? TimeSpan.FromMilliseconds(ms) + : timeout; + // Phase 1: bare TCP preflight — fast rejection for unreachable hosts. var sw = Stopwatch.StartNew(); try @@ -71,9 +79,9 @@ public sealed class S7DriverProbe : IDriverProbe var plc = S7Tsap.Resolve(opts) is { } tsap ? new Plc(host, port, tsap) : new Plc(S7CpuTypeMap.ToS7Net(opts.CpuType), host, port, opts.Rack, opts.Slot); - plc.ReadTimeout = (int)timeout.TotalMilliseconds; + plc.ReadTimeout = (int)opTimeout.TotalMilliseconds; using var handshakeCts = CancellationTokenSource.CreateLinkedTokenSource(ct); - handshakeCts.CancelAfter(timeout); + handshakeCts.CancelAfter(opTimeout); try { await plc.OpenAsync(handshakeCts.Token); @@ -148,4 +156,31 @@ public sealed class S7DriverProbe : IDriverProbe private static (string host, int port) ExtractTarget(S7DriverOptions opts) => (opts.Host, opts.Port); + + /// + /// The config's timeoutMs (any casing, as the driver factory binds it), or null when absent + /// or not a positive integer. + /// + /// The driver config. + /// The configured per-operation timeout in milliseconds, or null. + internal static int? ReadTimeoutMs(string configJson) + { + try + { + using var doc = JsonDocument.Parse(configJson); + if (doc.RootElement.ValueKind != JsonValueKind.Object) return null; + foreach (var prop in doc.RootElement.EnumerateObject()) + { + if (!string.Equals(prop.Name, "timeoutMs", StringComparison.OrdinalIgnoreCase)) continue; + return prop.Value.ValueKind == JsonValueKind.Number && prop.Value.TryGetInt32(out var ms) && ms > 0 + ? ms + : null; + } + return null; + } + catch (JsonException) + { + return null; + } + } } diff --git a/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7ProbeContentionAndTimeoutTests.cs b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7ProbeContentionAndTimeoutTests.cs new file mode 100644 index 00000000..6289a9ea --- /dev/null +++ b/tests/Drivers/ZB.MOM.WW.OtOpcUa.Driver.S7.Tests/S7ProbeContentionAndTimeoutTests.cs @@ -0,0 +1,121 @@ +using System.Net; +using System.Net.Sockets; +using Shouldly; +using Xunit; +using ZB.MOM.WW.OtOpcUa.Core.Abstractions; + +namespace ZB.MOM.WW.OtOpcUa.Driver.S7.Tests; + +/// +/// R07:H7 — (a) the background probe used to report the host Stopped whenever a long read +/// pass held the gate past the probe deadline: contention is the connection being USED, not lost; +/// (b) Test Connect ignored the config's timeoutMs. Waits are condition waits on counters and +/// events; bounds are generous. +/// +[Trait("Category", "Unit")] +public sealed class S7ProbeContentionAndTimeoutTests +{ + private static readonly TimeSpan Bound = TimeSpan.FromSeconds(15); + + private static async Task WaitUntilAsync(Func condition, CancellationToken ct) + { + using var cts = CancellationTokenSource.CreateLinkedTokenSource(ct); + cts.CancelAfter(Bound); + while (!condition()) + await Task.Delay(20, cts.Token); // polling a condition, not asserting on elapsed time + } + + /// A read pass holding the gate past the probe deadline does not make the host Stopped. + [Fact] + public async Task Gate_contention_is_no_verdict_but_a_real_probe_failure_still_is() + { + var ct = TestContext.Current.CancellationToken; + var factory = new ScriptedS7PlcFactory(); + var readEntered = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + var releaseRead = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + using var drv = new S7Driver(new S7DriverOptions + { + Host = "192.0.2.1", + Timeout = TimeSpan.FromSeconds(30), + Probe = new S7ProbeOptions { Enabled = true, Interval = TimeSpan.FromMilliseconds(50), Timeout = TimeSpan.FromSeconds(1) }, + RawTags = S7RawTags.Entries(new S7TagDefinition("W0", "DB1.DBW0", S7DataType.UInt16, Writable: false)), + }, "s7-probe-contention", factory); + var transitions = new List(); + drv.OnHostStatusChanged += (_, e) => { lock (transitions) transitions.Add(e.NewState); }; + await drv.InitializeAsync("{}", ct); + + await WaitUntilAsync(() => drv.GetHostStatuses()[0].State == HostState.Running, ct); + + // A read that holds the gate until released. + factory.Read = async (_, token) => + { + readEntered.TrySetResult(); + await releaseRead.Task.WaitAsync(token); + return (ushort)1; + }; + var read = drv.ReadAsync(["W0"], ct); + await readEntered.Task.WaitAsync(Bound, ct); + + // At least two probe ticks give up on the gate... + var contentionsBefore = drv.ProbeGateContentions; + await WaitUntilAsync(() => drv.ProbeGateContentions >= contentionsBefore + 2, ct); + // ...and the host is still Running — no Stopped transition was published for them. + drv.GetHostStatuses()[0].State.ShouldBe(HostState.Running); + lock (transitions) transitions.ShouldNotContain(HostState.Stopped); + + releaseRead.SetResult(); + (await read.WaitAsync(Bound, ct))[0].StatusCode.ShouldBe(0u); + + // Positive control: a genuine probe failure still reports Stopped. + factory.ReadStatus = _ => throw new System.IO.IOException("connection reset"); + await WaitUntilAsync(() => drv.GetHostStatuses()[0].State == HostState.Stopped, ct); + } + + /// Test Connect's handshake is bounded by the config's timeoutMs, not the caller's whole budget. + [Fact] + public async Task Test_connect_honours_the_config_timeoutMs() + { + var ct = TestContext.Current.CancellationToken; + // A TCP endpoint that accepts and then never answers the ISO-on-TCP handshake. + var listener = new TcpListener(IPAddress.Loopback, 0); + listener.Start(); + var held = new List(); + _ = Task.Run(async () => + { + try { while (true) { var c = await listener.AcceptTcpClientAsync(ct); lock (held) held.Add(c); } } + catch { /* stopped */ } + }, ct); + try + { + var port = ((IPEndPoint)listener.LocalEndpoint).Port; + var json = $$"""{"host":"127.0.0.1","port":{{port}},"timeoutMs":1000}"""; + + // The caller's budget (60 s) is far beyond the safety token (20 s): only a probe that honours + // timeoutMs returns its own "handshake failed: timed out"; one that waits the caller's budget + // is cut by the safety token and reports the caller-timeout message instead. + using var safety = CancellationTokenSource.CreateLinkedTokenSource(ct); + safety.CancelAfter(TimeSpan.FromSeconds(20)); + var r = await new S7DriverProbe().ProbeAsync(json, TimeSpan.FromSeconds(60), safety.Token); + + r.Ok.ShouldBeFalse(); + r.Message!.ShouldContain("handshake failed: timed out"); + safety.IsCancellationRequested.ShouldBeFalse(); + } + finally + { + listener.Stop(); + lock (held) foreach (var c in held) c.Dispose(); + } + } + + /// The config reader: any casing, positive integers only. + [Fact] + public void ReadTimeoutMs_reads_the_driver_key() + { + S7DriverProbe.ReadTimeoutMs("""{"TimeoutMs":2500}""").ShouldBe(2500); + S7DriverProbe.ReadTimeoutMs("""{"timeoutms":10}""").ShouldBe(10); + S7DriverProbe.ReadTimeoutMs("""{"timeoutMs":0}""").ShouldBeNull(); + S7DriverProbe.ReadTimeoutMs("""{"host":"x"}""").ShouldBeNull(); + S7DriverProbe.ReadTimeoutMs("not json").ShouldBeNull(); + } +}