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(); + } +}