test(abcip): hw5 hardware gate — #566 idle close drops TCP; native STRING write on Z-35162 (#592)

A. #566 on a real CompactLogix (Z-35162, read-only): a class-3 connection idled 60 s past its 16 s timeout is closed at the TCP level, not with CIP 0x0107/0x0203; the next request fails on its write (Broken pipe -> BadConnection) in 9 ms and the one after reopens. The transport already handles this, so no production behaviour changed; the shape is pinned offline by CipConnectionTests.A_target_that_resets_an_idle_session_... (FakeEipServer.ResetAllConnections), proven red with a reconnect-skipping mutation. The diagnostics-only exchange tap now also sees Forward Open replies (granted RPIs). B. Native STRING write through the driver on Program:ES03_TemperatureControl._StrTmp: write, read back, restored byte-exact (user-approved). Array write NOT run: the census's unreferenced DINT[32] _SEQ_EP arrays are aliased sequencer step registers (raw L5X grep), so none qualifies. #567 still impossible (a 128 B array / 88 B STRING never fragments). New env-gated harness: AbCip.IntegrationTests/HardwareGate (IdleConnectionEvidenceTests, StringWriteGateTests). Docs: gate results (hw5 section + raw output), AbCip.md, CLAUDE.md. Claude-Session: https://claude.ai/code/session_01Ef2ozxS7QPanGT8uoATbTe
2026-10-09 06:16:16 -04:00
parent 98c00904e7
commit 1f983d610f
11 changed files with 488 additions and 15 deletions
@@ -565,6 +565,36 @@ public sealed class CipConnectionTests
        target.ForwardOpens.ShouldBe(2);
    }

+    [Fact]
+    public async Task A_target_that_resets_an_idle_session_fails_the_next_request_fast_and_the_one_after_reopens()
+    {
+        // The shape a real CompactLogix produced (Z-35162, hw5 #566 gate): a session idle past its connection
+        // timeout was reset with NO CIP status, so the next write hit a dead socket ("Broken pipe"). It must surface
+        // at once as BadConnection (not wait out the exchange timeout), must not count as a CIP-level close, and the
+        // request after it must reopen with a fresh Forward Open.
+        await using var target = new FakeCipTarget();
+        target.ConnectedHandler = cip => Task.FromResult<byte[]?>(Ok(cip));
+        var time = new ManualTimeProvider();
+        await using var conn = Create(target, Options(timeoutSeconds: 5), time);
+        await conn.SendAsync(ReadTag, TestCt);
+
+        target.Server.ResetAllConnections();
+        await FakeCipTarget.Until(() => target.Server.OpenConnections == 0, Guard, "the reset to land");
+        var started = System.Diagnostics.Stopwatch.StartNew();
+        var ex = await Should.ThrowAsync<AbTransportException>(() => conn.SendAsync(ReadTag, TestCt));
+        ex.Status.ShouldBe(AbStatus.BadConnection);
+        started.Elapsed.ShouldBeLessThan(TimeSpan.FromSeconds(4), "a dead socket is not a timeout");
+        conn.Diagnostics.ConnectionsClosedByTarget.ShouldBe(0);   // no CIP status was involved
+        target.ForwardOpens.ShouldBe(1);
+
+        var reopen = conn.SendAsync(ReadTag, TestCt);
+        await time.WaitForTimerDueAtAsync(time.Start + TimeSpan.FromSeconds(1), Guard);   // through the throttle
+        time.Advance(TimeSpan.FromSeconds(1));
+        CipReply.Parse(await reopen.WaitAsync(Guard, TestCt)).GeneralStatus.ShouldBe((byte)0);
+        target.ForwardOpens.ShouldBe(2);
+        target.Server.Connections.ShouldBe(2);
+    }
+
    [Fact]
    public async Task Other_error_statuses_describe_the_request_and_leave_the_connection_alone()
    {
@@ -73,6 +73,24 @@ internal sealed class FakeEipServer : IAsyncDisposable
    /// <summary>Close the connection instead of answering the next non-session request.</summary>
    public bool DropOnNextRequest { get; set; }

+    /// <summary>
+    ///     Reset every accepted connection (SO_LINGER 0 ⇒ RST) without any request in flight — what a real Logix
+    ///     (Z-35162, Gitea #566 hw5 gate) did to a class-3 session left idle past its connection timeout: no CIP
+    ///     status, the next request's write just fails on a dead socket.
+    /// </summary>
+    public void ResetAllConnections()
+    {
+        foreach (var c in _clients)
+        {
+            try
+            {
+                c.Client.LingerState = new LingerOption(true, 0);
+                c.Client.Close();
+            }
+            catch (ObjectDisposedException) { /* already gone */ }
+        }
+    }
+
    /// <summary>Queue one-shot responders, consumed one per non-session request.</summary>
    public void Script(params Func<byte[], byte[]?>[] steps)
    {
@@ -0,0 +1,136 @@
+using System.Buffers.Binary;
+using System.Diagnostics;
+using System.Globalization;
+using System.Net.Sockets;
+using Shouldly;
+using Xunit;
+using ZB.MOM.WW.OtOpcUa.Driver.Ab.Transport;
+using ZB.MOM.WW.OtOpcUa.Driver.Ab.Transport.Cip;
+using ZB.MOM.WW.OtOpcUa.Driver.Ab.Transport.Logix;
+using ZB.MOM.WW.OtOpcUa.Driver.AbCip.IntegrationTests.Differential;
+
+namespace ZB.MOM.WW.OtOpcUa.Driver.AbCip.IntegrationTests.HardwareGate;
+
+/// <summary>
+///     Gitea #566 hardware evidence (hw5): what a real Logix does with a class-3 connection that has been left idle
+///     past its connection timeout. READ-ONLY: three Read Tag requests of one tag on one private pool, nothing else.
+///     <list type="bullet">
+///         <item>Opt-in: <c>AB_DIFF_ENDPOINT</c> (the target, see <see cref="DifferentialTarget"/>) AND
+///             <c>AB_EVID_IDLE=1</c>.</item>
+///         <item><c>AB_EVID_IDLE_TAG</c> — the tag read, default <c>test2</c> (a DINT).</item>
+///         <item><c>AB_EVID_IDLE_SECONDS</c> — idle time, default 60, in [1, 300]. It must exceed the expiry the
+///             controller grants (logged from the Forward Open reply), or the read just succeeds.</item>
+///     </list>
+///     The keep-alive is pushed out to one hour on this private pool so nothing touches the connection while it is
+///     idle (in production it fires every half expiry, which is why this case only arises after a controller
+///     restart / re-download or a network gap). The open-attempt budget is 2: the first open and one reconnect.
+/// </summary>
+[Trait("Category", "LiveIntegration")]
+public sealed class IdleConnectionEvidenceTests
+{
+    private const string DefaultTag = "test2";
+
+    [Fact]
+    public async Task An_idle_connection_past_its_timeout_reports_what_the_controller_does_and_recovers()
+    {
+        var target = DifferentialTarget.FromEnvironment();
+        if (target is null) Assert.Skip(DifferentialTarget.SkipReason);
+        if (Environment.GetEnvironmentVariable("AB_EVID_IDLE") != "1") Assert.Skip("AB_EVID_IDLE=1 not set.");
+        var tag = Environment.GetEnvironmentVariable("AB_EVID_IDLE_TAG") is { Length: > 0 } t ? t.Trim() : DefaultTag;
+        var idleSeconds = 60;
+        if (Environment.GetEnvironmentVariable("AB_EVID_IDLE_SECONDS") is { Length: > 0 } rawIdle
+            && (!int.TryParse(rawIdle, NumberStyles.None, CultureInfo.InvariantCulture, out idleSeconds) || idleSeconds is < 1 or > 300))
+            throw new InvalidOperationException($"AB_EVID_IDLE_SECONDS='{rawIdle}' must be an integer in [1, 300].");
+
+        using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(idleSeconds + 120));
+        var ct = cts.Token;
+        var pool = new DeviceSessionPool();
+        var diagnostics = pool.Diagnostics;
+        var p = target.Params(tag);
+        var key = NativeAbCipDevice.Key(p);
+        var options = NativeAbCipDevice.Options(p) with { KeepAliveInterval = TimeSpan.FromHours(1) };
+        var clock = Stopwatch.StartNew();
+        var log = new List<string>();
+        void Note(string line)
+        {
+            var stamped = $"[{clock.Elapsed.TotalSeconds,7:F2} s] {line}";
+            log.Add(stamped);
+            TestContext.Current.TestOutputHelper?.WriteLine(stamped);
+        }
+
+        diagnostics.ExchangeObserver = (req, rep) => Note(DescribeExchange(req.Span, rep.Span));
+        using var budget = diagnostics.LimitOpenAttempts(key, 2);
+        var request = LogixServices.ReadTag(CipPath.EncodeSymbolic(tag), 1);
+        Note($"Target {target}; tag '{tag}'; requested RPI {options.RpiMicros} us both ways, timeout multiplier " +
+             $"{options.TimeoutMultiplier} (x{4 << options.TimeoutMultiplier}) => expiry {options.ConnectionExpiry.TotalSeconds:F1} s; " +
+             $"keep-alive pushed to {options.KeepAliveInterval}; idle {idleSeconds} s");
+
+        var lease = pool.Acquire(key, options);
+        try
+        {
+            var first = await ReadAsync("read 1 (opens)", lease.Channel, request, Note, ct);
+            first.ShouldBeTrue("the first read must succeed, or there is no connection to idle");
+            Note($"Forward Opens {diagnostics.ForwardOpens}; now idle for {idleSeconds} s with no traffic");
+            await Task.Delay(TimeSpan.FromSeconds(idleSeconds), ct);
+
+            var opensBefore = diagnostics.ForwardOpens;
+            var second = await ReadAsync("read 2 (after idle)", lease.Channel, request, Note, ct);
+            Note($"After read 2: Forward Opens {diagnostics.ForwardOpens} (delta {diagnostics.ForwardOpens - opensBefore}), " +
+                 $"closed-by-target {diagnostics.ConnectionsClosedByTarget}, success={second}");
+
+            await Task.Delay(TimeSpan.FromSeconds(2), ct);   // past the 1 s Forward Open interval
+            var third = await ReadAsync("read 3 (recovery)", lease.Channel, request, Note, ct);
+            Note($"After read 3: Forward Opens {diagnostics.ForwardOpens}, closed-by-target " +
+                 $"{diagnostics.ConnectionsClosedByTarget}, open attempts used {budget.Attempts}/{budget.Budget}, success={third}");
+            third.ShouldBeTrue("the transport must recover on the request after the failed one");
+        }
+        finally
+        {
+            await lease.DisposeAsync();
+            diagnostics.ExchangeObserver = null;
+            Note($"Lease released: Forward Closes sent/acked {diagnostics.ForwardClosesSent}/{diagnostics.ForwardClosesAcked}");
+        }
+    }
+
+    private static async Task<bool> ReadAsync(string label, ICipChannel channel, byte[] request, Action<string> note,
+        CancellationToken ct)
+    {
+        var sw = Stopwatch.StartNew();
+        try
+        {
+            var reply = CipReply.Parse(await channel.SendAsync(request, ct));
+            note($"{label}: reply in {sw.ElapsedMilliseconds} ms, general 0x{reply.GeneralStatus:X2}" +
+                 $"{(reply.ExtendedStatus.Length > 0 ? $" extended {string.Join(",", reply.ExtendedStatus.Select(e => $"0x{e:X4}"))}" : "")}");
+            return reply.GeneralStatus == 0;
+        }
+        catch (AbTransportException ex)
+        {
+            note($"{label}: THREW after {sw.ElapsedMilliseconds} ms: AbTransportException status={ex.Status} " +
+                 $"(OPC UA 0x{AbOpcUaStatusMap.MapStatus(ex.Status):X8}) message='{ex.Message}' inner={Inner(ex)}");
+            return false;
+        }
+    }
+
+    private static string Inner(Exception ex)
+    {
+        var parts = new List<string>();
+        for (var e = ex.InnerException; e is not null; e = e.InnerException)
+            parts.Add(e is SocketException se ? $"SocketException({se.SocketErrorCode})" : $"{e.GetType().Name}('{e.Message}')");
+        return parts.Count == 0 ? "none" : string.Join(" <- ", parts);
+    }
+
+    private static string DescribeExchange(ReadOnlySpan<byte> request, ReadOnlySpan<byte> reply)
+    {
+        var service = request.Length > 0 ? request[0] : (byte)0;
+        var hex = Convert.ToHexString(reply[..Math.Min(reply.Length, 48)]);
+        if (service is 0x54 or 0x5B && reply.Length >= 4 && reply[2] == 0)
+        {
+            // Forward Open reply data: O->T id, T->O id, serial, vendor, originator serial, O->T API, T->O API.
+            var d = reply[(4 + 2 * reply[3])..];
+            if (d.Length >= 24)
+                return $"Forward Open 0x{service:X2} granted: O->T id 0x{BinaryPrimitives.ReadUInt32LittleEndian(d):X8}, " +
+                       $"O->T API {BinaryPrimitives.ReadUInt32LittleEndian(d[16..])} us, T->O API {BinaryPrimitives.ReadUInt32LittleEndian(d[20..])} us; raw {hex}";
+        }
+        return $"exchange: request service 0x{service:X2} ({request.Length} B) -> reply {reply.Length} B: {hex}";
+    }
+}
@@ -0,0 +1,164 @@
+using System.Text;
+using Shouldly;
+using Xunit;
+using ZB.MOM.WW.OtOpcUa.Core.Abstractions;
+using ZB.MOM.WW.OtOpcUa.Driver.Ab.Transport;
+
+namespace ZB.MOM.WW.OtOpcUa.Driver.AbCip.IntegrationTests.HardwareGate;
+
+/// <summary>
+///     Gitea #592 (hw5) — ONE user-approved native STRING write on a real controller, through the production driver
+///     (<see cref="AbCipDriver"/>, native transport): snapshot twice ≥ 30 s apart (raw bytes, from the exchange tap),
+///     write a distinctive value, read it back, restore the exact original, read back, final raw snapshot equals the
+///     original. Fails closed before ANY write when the tag is not a built-in 88-byte STRING, moved between the two
+///     snapshots, or holds non-zero bytes past its LEN (the driver's encoder zero-fills, so such a value could not be
+///     restored byte-exact).
+///     <list type="bullet">
+///         <item><c>AB_HW_WRITE_GATEWAY</c> — <c>ab://host/1,0</c>; absent ⇒ skip.</item>
+///         <item><c>AB_HW_WRITE_STRING_TAG</c> — must be one of <see cref="Approved"/> (the brief's allow-list).</item>
+///         <item><c>AB_HW_WRITE_APPROVED=1</c> — the explicit opt-in.</item>
+///         <item><c>AB_HW_WRITE_GAP_SECONDS</c> — snapshot gap, default 30, at least 30.</item>
+///         <item><c>AB_HW_WRITE_DRYRUN=1</c> — stop after the read-only preflight (no write).</item>
+///     </list>
+///     Never set by any other run; <see cref="IntegrationWriteGate"/> (the simulator opt-in) is deliberately not
+///     what enables this.
+/// </summary>
+[Trait("Category", "LiveIntegration")]
+public sealed class StringWriteGateTests
+{
+    /// <summary>The only tags this gate may write: logic-, alias-, trend- and Galaxy-unreferenced (L5X census + raw grep).</summary>
+    private static readonly string[] Approved =
+    [
+        "Program:ES03_TemperatureControl._StrTmp",
+        "Program:ES03_TemperatureControl._Prefix",
+    ];
+
+    private const string TestValue = "OTOPCUA-TEST";
+    private const int BuiltInStringBytes = 88;
+    private const int StringCapacity = 82;
+
+    [Fact]
+    public async Task A_native_STRING_write_reads_back_and_restores_the_exact_original()
+    {
+        var gateway = Environment.GetEnvironmentVariable("AB_HW_WRITE_GATEWAY")?.Trim();
+        if (string.IsNullOrEmpty(gateway)) Assert.Skip("AB_HW_WRITE_GATEWAY not set.");
+        if (Environment.GetEnvironmentVariable("AB_HW_WRITE_APPROVED") != "1") Assert.Skip("AB_HW_WRITE_APPROVED=1 not set.");
+        var tagPath = Environment.GetEnvironmentVariable("AB_HW_WRITE_STRING_TAG")?.Trim() ?? "";
+        if (!Approved.Contains(tagPath, StringComparer.Ordinal))
+            throw new InvalidOperationException($"AB_HW_WRITE_STRING_TAG='{tagPath}' is not on the approved list.");
+        var gap = 30;
+        if (Environment.GetEnvironmentVariable("AB_HW_WRITE_GAP_SECONDS") is { Length: > 0 } rawGap
+            && (!int.TryParse(rawGap, out gap) || gap < 30 || gap > 300))
+            throw new InvalidOperationException($"AB_HW_WRITE_GAP_SECONDS='{rawGap}' must be in [30, 300].");
+
+        using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(gap + 120));
+        var ct = cts.Token;
+        const string Ref = "gate-string";
+        var diagnostics = DeviceSessionPool.Shared.Diagnostics;
+        var replies = new List<byte[]>();
+        diagnostics.ExchangeObserver = (req, rep) =>
+        {
+            // Read Tag Fragmented (0x52) replies only: service 0xD2, status 0, then type 0x02A0 + handle + data.
+            if (req.Length > 0 && req.Span[0] == 0x52) lock (replies) replies.Add(rep.ToArray());
+        };
+
+        var drv = new AbCipDriver(new AbCipDriverOptions
+        {
+            Devices = [new AbCipDeviceOptions(gateway, AbCipPlcFamily.CompactLogix, DeviceName: "hw5-gate")],
+            RawTags =
+            [
+                new RawTagEntry(Ref, $$"""{"tagPath":"{{tagPath}}","dataType":"String","writable":true}""",
+                    WriteIdempotent: false, DeviceName: gateway),
+            ],
+            Timeout = TimeSpan.FromSeconds(5),
+            Transport = AbCipTransport.Native,
+            Probe = new AbCipProbeOptions { Enabled = false },
+            EnableControllerBrowse = false,
+            EnableAlarmProjection = false,
+        }, "hw5-string-gate");
+        try
+        {
+            await drv.InitializeAsync("{}", ct);
+            Log($"Gateway {gateway}; tag '{tagPath}'; transport Native; snapshot gap {gap} s");
+
+            var (v1, raw1) = await SnapshotAsync(drv, Ref, replies, "snapshot 1", ct);
+            await Task.Delay(TimeSpan.FromSeconds(gap), ct);
+            var (v2, raw2) = await SnapshotAsync(drv, Ref, replies, "snapshot 2", ct);
+
+            // Preflight — fail closed before any write.
+            raw1.ShouldBe(raw2, "the tag changed between the two snapshots: something else writes it; NOT writing");
+            raw1.Length.ShouldBe(4 + BuiltInStringBytes, "expected a built-in STRING (type 0x02A0 + handle + 88 bytes)");
+            var data = raw1.AsSpan(4);
+            var len = BitConverter.ToInt32(data[..4]);
+            len.ShouldBeInRange(0, StringCapacity);
+            data[(4 + len)..].ToArray().ShouldAllBe(b => b == 0,
+                "bytes past LEN are not zero, so the driver's zero-filling encoder could not restore them exactly; NOT writing");
+            Log($"Preflight OK: type/handle {Convert.ToHexString(raw1.AsSpan(0, 4))}, LEN {len}, tail zero; original '{v1}'");
+            if (Environment.GetEnvironmentVariable("AB_HW_WRITE_DRYRUN") == "1")
+            {
+                Log("AB_HW_WRITE_DRYRUN=1: stopping after the read-only preflight; nothing written.");
+                return;
+            }
+
+            var restored = false;
+            byte[] rawTest;
+            try
+            {
+                await WriteAsync(drv, Ref, TestValue, "write test value", ct);
+                (var vTest, rawTest) = await SnapshotAsync(drv, Ref, replies, "read back test value", ct);
+                vTest.ShouldBe(TestValue);
+                await WriteAsync(drv, Ref, v1, "restore original", ct);
+                restored = true;
+            }
+            finally
+            {
+                // Whatever failed after the first write, the original goes back (own token: never skip the restore).
+                if (!restored) await WriteAsync(drv, Ref, v1, "restore original (after a failure)", CancellationToken.None);
+            }
+            var (vRestored, rawRestored) = await SnapshotAsync(drv, Ref, replies, "read back restored", ct);
+            vRestored.ShouldBe(v1);
+            rawRestored.ShouldBe(raw1, "restored bytes must equal the original byte for byte");
+            Log($"Test-value raw LEN {BitConverter.ToInt32(rawTest.AsSpan(4, 4))}; restored raw equals original: {rawRestored.SequenceEqual(raw1)}");
+
+            await Task.Delay(TimeSpan.FromSeconds(2), ct);
+            var (vFinal, rawFinal) = await SnapshotAsync(drv, Ref, replies, "final snapshot", ct);
+            rawFinal.ShouldBe(raw1);
+            vFinal.ShouldBe(v1);
+            Log("RESULT: write, read-back, exact restore — PASS");
+        }
+        finally
+        {
+            diagnostics.ExchangeObserver = null;
+            await drv.ShutdownAsync(CancellationToken.None);
+        }
+    }
+
+    private static async Task<(string Value, byte[] Raw)> SnapshotAsync(
+        AbCipDriver drv, string reference, List<byte[]> replies, string label, CancellationToken ct)
+    {
+        lock (replies) replies.Clear();
+        var snap = (await drv.ReadAsync([reference], ct)).Single();
+        byte[] reply;
+        lock (replies)
+        {
+            // The first read of a fresh runtime is two wire reads (the create/existence read, then the read itself).
+            replies.Count.ShouldBeInRange(1, 2, $"{label}: Read Tag Fragmented replies on the wire");
+            replies.ShouldAllBe(r => r.SequenceEqual(replies[0]), $"{label}: the wire reads of one call disagree");
+            reply = replies[^1];
+        }
+        reply[2].ShouldBe((byte)0, $"{label}: CIP general status");
+        var raw = reply.AsSpan(4).ToArray();   // type (2) + handle (2) + data
+        Log($"{label}: status 0x{snap.StatusCode:X8}, value '{snap.Value}', raw ({raw.Length} B) {Convert.ToHexString(raw)}");
+        snap.StatusCode.ShouldBe(0u, label);
+        return ((string)snap.Value!, raw);
+    }
+
+    private static async Task WriteAsync(AbCipDriver drv, string reference, string value, string label, CancellationToken ct)
+    {
+        var result = (await drv.WriteAsync([new WriteRequest(reference, value)], ct)).Single();
+        Log($"{label}: '{value}' (ASCII {Convert.ToHexString(Encoding.ASCII.GetBytes(value))}) -> status 0x{result.StatusCode:X8}");
+        result.StatusCode.ShouldBe(0u, label);
+    }
+
+    private static void Log(string line) => TestContext.Current.TestOutputHelper?.WriteLine(line);
+}