riojoy/tools/RioSerialMonitor/MashTest.cs

using System.Diagnostics;
using RioJoy.Core.Mapping;
using RioJoy.Core.Protocol;
using RioJoy.Core.Serial;

namespace RioSerialMonitor;

/// <summary>
/// Instrumented firmware mash test (the RIO_TAP protocol, mechanized) for
/// validating the RIOv4.2 reply-latch wedge patch — see
/// rio-firmware/RIOv4_2-ANALYSIS.md "Validation plan".
///
/// Runs the live link with the app's own &gt;5s reset-recovery DISABLED (so a
/// board wedge stays observable instead of being revived by our watchdog),
/// echoes lamps on every press (lamp writes colliding with analog replies are
/// the wedge trigger), and records:
///   - an inter-analog-reply gap histogram + the longest gaps with timestamps
///     (gap timing uses ANY AnalogReply packet, valid or 0xFE-sentinel — a
///     sentinel still proves the reply path is alive);
///   - WEDGE events: analog silent past the threshold while button traffic
///     continues; on resume, whether it self-recovered or was revived by a
///     button press (the known unpatched revival mechanism);
///   - the board's own RestartCount/AbandonCount/FullBufferCount before and
///     after (CheckReply), with the delta;
///   - a fixed-layout summary block, teed to a log file, so runs on the
///     original vs patched chip diff cleanly.
///
/// Usage:
///   dotnet run --project tools/RioSerialMonitor -- --mash [port] [seconds]
///       [--label name] [--no-lamps] [--wedge seconds]
/// Defaults: COM1, 300 s, label "unlabeled", lamps on, wedge threshold 2 s.
/// Exit: 0 = ran with no wedge, 1 = wedge detected, 2 = could not open port.
/// </summary>
internal static class MashTest
{
    private sealed class WedgeEvent
    {
        public TimeSpan Start;
        public TimeSpan Duration;
        public int ButtonEventsDuring;
        public bool RevivedByButton;
        public bool Unresolved; // run ended while still wedged
    }

    public static async Task<int> RunAsync(string[] args)
    {
        // --- args ------------------------------------------------------------
        string port = "COM1";
        int seconds = 300;
        string label = "unlabeled";
        bool lampEcho = true;
        double wedgeSec = 2.0;
        bool selftest = false;
        int baud = 9600;

        var positional = new List<string>();
        for (int i = 0; i < args.Length; i++)
        {
            switch (args[i])
            {
                case "--mash": break;
                case "--no-lamps": lampEcho = false; break;
                case "--selftest": selftest = true; break;
                case "--label" when i + 1 < args.Length: label = args[++i]; break;
                case "--wedge" when i + 1 < args.Length && double.TryParse(args[i + 1], out double w):
                    wedgeSec = w; i++; break;
                case "--baud" when i + 1 < args.Length && int.TryParse(args[i + 1], out int b):
                    baud = b; i++; break;
                default: positional.Add(args[i]); break;
            }
        }
        if (positional.Count > 0) port = positional[0];
        if (positional.Count > 1 && int.TryParse(positional[1], out int s)) seconds = s;
        if (selftest)
        {
            // Scripted board (SelftestTransport): short fixed run, expect exactly
            // one button-revived wedge and a +4/+1 counter delta → exit 1.
            port = "selftest";
            seconds = 10;
            if (label == "unlabeled") label = "selftest";
        }

        string logPath = $"riomash-{label}-{DateTime.Now:yyyyMMdd-HHmmss}.log";
        using var logFile = new StreamWriter(logPath) { AutoFlush = true };

        var gate = new object();
        var sw = Stopwatch.StartNew();
        void Log(string msg)
        {
            lock (gate)
            {
                string line = $"[{sw.Elapsed.TotalSeconds,7:F2}s] {msg}";
                Console.WriteLine(line);
                logFile.WriteLine(line);
            }
        }
        void Raw(string msg)
        {
            lock (gate) { Console.WriteLine(msg); logFile.WriteLine(msg); }
        }

        Raw($"== RIO mash test :: {port} @ {baud} 8N1, {seconds}s, chip label '{label}' ==");
        Raw($"   lamp echo {(lampEcho ? "ON (drives reply/lamp collisions)" : "OFF")}, " +
            $"wedge threshold {wedgeSec:F1}s, app auto-recovery DISABLED");
        Raw($"   log: {Path.GetFullPath(logPath)}");

        IRioTransport transport;
        try
        {
            transport = selftest ? new SelftestTransport() : new SerialPortTransport(port, baud);
        }
        catch (Exception ex)
        {
            Raw($"  FAILED to open {port}: {ex.GetType().Name}: {ex.Message}");
            return 2;
        }

        // Recovery timeout effectively infinite: a wedge must be OURS to observe,
        // not silently repaired by the link's legacy >5s general-reset rule.
        var link = new RioSerialLink(transport, new RioSerialLinkOptions
        {
            AnalogRecoveryTimeout = TimeSpan.FromDays(365),
        });

        // --- shared state (guarded by 'gate') ---------------------------------
        int presses = 0, releases = 0, framing = 0, naks = 0, sentinels = 0;
        long analogReplies = 0;
        TimeSpan lastAnalog = TimeSpan.Zero;
        TimeSpan lastButton = TimeSpan.MinValue;

        // Gap histogram buckets (upper bounds in ms; last = overflow).
        double[] bucketMs = { 100, 250, 500, 1000, 2000, 5000, double.MaxValue };
        string[] bucketNames = { "<100ms", "100-250ms", "250-500ms", "0.5-1s", "1-2s", "2-5s", ">5s" };
        long[] buckets = new long[bucketMs.Length];
        var longestGaps = new List<(TimeSpan At, double Ms)>(); // keep top 10

        bool inWedge = false;
        var currentWedge = default(WedgeEvent);
        var wedges = new List<WedgeEvent>();
        bool statusCollecting = false;
        var statusItems = new List<CheckStatus>();
        VersionInfo? version = null;

        void NoteGap(double ms, TimeSpan at)
        {
            for (int i = 0; i < bucketMs.Length; i++)
            {
                if (ms <= bucketMs[i]) { buckets[i]++; break; }
            }
            longestGaps.Add((at, ms));
            if (longestGaps.Count > 10)
            {
                longestGaps.Sort((a, b) => b.Ms.CompareTo(a.Ms));
                longestGaps.RemoveAt(10);
            }
        }

        link.PacketReceived += p =>
        {
            lock (gate)
            {
                switch (p.Command)
                {
                    case RioCommand.AnalogReply:
                    {
                        TimeSpan now = sw.Elapsed;
                        analogReplies++;
                        foreach (byte b in p.Payload)
                        {
                            if (b == (byte)RioControl.Restart) { sentinels++; break; }
                        }
                        if (lastAnalog != TimeSpan.Zero)
                            NoteGap((now - lastAnalog).TotalMilliseconds, lastAnalog);

                        if (inWedge && currentWedge is not null)
                        {
                            currentWedge.Duration = now - currentWedge.Start;
                            currentWedge.RevivedByButton =
                                lastButton > currentWedge.Start &&
                                (now - lastButton) < TimeSpan.FromMilliseconds(300);
                            wedges.Add(currentWedge);
                            Log($"*** WEDGE ENDED after {currentWedge.Duration.TotalSeconds:F2}s — " +
                                (currentWedge.RevivedByButton
                                    ? "revived by a button press (unpatched-firmware signature)"
                                    : "self-recovered (patched-firmware expectation)") +
                                $", {currentWedge.ButtonEventsDuring} button events during");
                            inWedge = false;
                            currentWedge = null;
                        }
                        lastAnalog = now;
                        break;
                    }

                    case RioCommand.ButtonPressed:
                    case RioCommand.KeyPressed:
                        presses++;
                        lastButton = sw.Elapsed;
                        if (inWedge && currentWedge is not null) currentWedge.ButtonEventsDuring++;
                        // Lamp echo on lamp buttons (keypads have none): the lamp
                        // number is the RIO address, not the raw button code.
                        if (lampEcho && p.Command == RioCommand.ButtonPressed &&
                            p.Payload[0] < RioAddress.ButtonCount)
                            _ = link.SetLampAsync((byte)RioAddress.FromButton(p.Payload[0]), RioLampState.SolidBright);
                        break;

                    case RioCommand.ButtonReleased:
                    case RioCommand.KeyReleased:
                        releases++;
                        lastButton = sw.Elapsed;
                        if (inWedge && currentWedge is not null) currentWedge.ButtonEventsDuring++;
                        if (lampEcho && p.Command == RioCommand.ButtonReleased &&
                            p.Payload[0] < RioAddress.ButtonCount)
                            _ = link.SetLampAsync((byte)RioAddress.FromButton(p.Payload[0]), RioLampState.SolidDim);
                        break;
                }
            }
        };

        link.VersionReceived += v => { lock (gate) version = v; };
        link.CheckReceived += c => { lock (gate) { if (statusCollecting) statusItems.Add(c); } };
        link.FramingError += () => { lock (gate) framing++; };
        link.ControlReceived += b => { if ((RioControl)b == RioControl.Nak) lock (gate) naks++; };

        using var cts = new CancellationTokenSource();
        Task run = link.RunAsync(cts.Token);

        // Ctrl+C = "my fingers hurt": end the run NOW but still snapshot the
        // counters and print the full summary, instead of dying summary-less
        // (and leaving an orphan holding the port, as an interrupted run did).
        bool stopRequested = false;
        Console.CancelKeyPress += (_, e) =>
        {
            e.Cancel = true; // we shut down ourselves
            stopRequested = true;
        };

        // --- counters BEFORE ---------------------------------------------------
        await Task.Delay(500);
        Dictionary<RioStatusType, int> before = await SnapshotStatusAsync();
        Raw($"   firmware: {(version is null ? "(no version reply!)" : version.ToString())}");
        Raw($"   counters before: {FormatCounters(before)}");
        Raw("");
        Raw(">>> MASH NOW: two hands, 8 lamp buttons, as fast as you can. <<<");
        Raw($">>> Test runs {seconds}s. A wedge alarm will beep + banner.   <<<");
        Raw(">>> Ctrl+C ends the run early and still prints the summary.   <<<");
        Raw("");

        // --- wedge watchdog + progress ticker ----------------------------------
        TimeSpan runEnd = sw.Elapsed + TimeSpan.FromSeconds(seconds);
        TimeSpan nextProgress = sw.Elapsed + TimeSpan.FromSeconds(30);
        while (sw.Elapsed < runEnd)
        {
            if (stopRequested)
            {
                seconds = (int)sw.Elapsed.TotalSeconds; // summary reflects reality
                Log("operator stop (Ctrl+C) — ending run, snapshotting counters...");
                break;
            }
            await Task.Delay(100);
            lock (gate)
            {
                if (!inWedge && lastAnalog != TimeSpan.Zero &&
                    (sw.Elapsed - lastAnalog).TotalSeconds > wedgeSec)
                {
                    inWedge = true;
                    currentWedge = new WedgeEvent { Start = lastAnalog };
                    Log($"*** WEDGE: no analog reply for >{wedgeSec:F1}s (last at {lastAnalog.TotalSeconds:F2}s). " +
                        "Keep pressing buttons — do NOT power cycle. ***");
                    try { Console.Beep(880, 400); } catch { /* no console beep available */ }
                }
            }

            if (sw.Elapsed >= nextProgress)
            {
                lock (gate)
                {
                    double rate = presses / Math.Max(1.0, sw.Elapsed.TotalMinutes);
                    double maxGap = longestGaps.Count > 0 ? longestGaps.Max(g => g.Ms) : 0;
                    Log($"progress: presses={presses} ({rate:F0}/min) analog={analogReplies} " +
                        $"maxGap={maxGap / 1000:F2}s wedges={wedges.Count}{(inWedge ? " [WEDGED NOW]" : "")}");
                }
                nextProgress = sw.Elapsed + TimeSpan.FromSeconds(30);
            }
        }

        // Close out an unresolved wedge.
        lock (gate)
        {
            if (inWedge && currentWedge is not null)
            {
                currentWedge.Duration = sw.Elapsed - currentWedge.Start;
                currentWedge.Unresolved = true;
                wedges.Add(currentWedge);
                Log($"*** RUN ENDED WHILE WEDGED ({currentWedge.Duration.TotalSeconds:F1}s and counting) ***");
            }
        }

        // --- counters AFTER ------------------------------------------------------
        Dictionary<RioStatusType, int> after = await SnapshotStatusAsync();

        // Dispose the transport BEFORE awaiting the link: on a wedged (silent)
        // board the receive loop sits in a pending serial read that ignores
        // cancellation — closing the port is what unblocks it. Awaiting first
        // hangs forever and eats the summary (seen on the baseline chip run).
        cts.Cancel();
        transport.Dispose();
        try { await run; } catch { /* shutdown */ }

        // --- summary (fixed layout for diffing runs) ------------------------------
        double mins = Math.Max(sw.Elapsed.TotalMinutes, 0.001);
        long expectedPolls = (long)(seconds * 1000.0 / 55.0);
        bool anyWedge = wedges.Count > 0;
        bool endedWedged = wedges.Any(w => w.Unresolved);
        bool anyButtonRevival = wedges.Any(w => w.RevivedByButton);

        Raw("");
        Raw($"== MASH SUMMARY [{label}] ==");
        Raw($"run              : {seconds}s on {port}, lamps {(lampEcho ? "on" : "off")}, wedge threshold {wedgeSec:F1}s");
        Raw($"firmware         : {(version is null ? "(no reply)" : version.ToString())}");
        Raw($"presses/releases : {presses} / {releases}  ({presses / mins:F0} presses/min)");
        Raw($"analog replies   : {analogReplies} (~{expectedPolls} poll slots; {100.0 * analogReplies / Math.Max(1, expectedPolls):F1}%), sentinels {sentinels}");
        Raw($"framing / NAK    : {framing} / {naks} (NAK-triggered resends: {link.NakRetransmits})");
        Raw("gap histogram    : " + string.Join("  ", bucketNames.Select((n, i) => $"{n}:{buckets[i]}")));
        Raw("longest gaps     : " + (longestGaps.Count == 0
            ? "(none)"
            : string.Join(", ", longestGaps.OrderByDescending(g => g.Ms).Take(10)
                .Select(g => $"{g.Ms / 1000:F2}s@{g.At.TotalSeconds:F1}s"))));
        Raw($"wedge events     : {wedges.Count}" + (wedges.Count == 0 ? "" :
            " — " + string.Join("; ", wedges.Select(w =>
                $"{w.Duration.TotalSeconds:F1}s@{w.Start.TotalSeconds:F1}s " +
                (w.Unresolved ? "UNRESOLVED" : w.RevivedByButton ? "button-revived" : "self-recovered")))));
        Raw($"counters before  : {FormatCounters(before)}");
        Raw($"counters after   : {FormatCounters(after)}");
        Raw($"counter delta    : {FormatDelta(before, after)}");

        string verdict =
            endedWedged      ? "FAIL — board wedged and never recovered (power cycle it now)" :
            anyButtonRevival ? "FAIL — wedge required a button press to revive (unpatched behavior)" :
            anyWedge         ? "MARGINAL — wedge(s) occurred but self-recovered; compare durations to baseline" :
                               "PASS — no wedge; compare gap histogram + counter delta to baseline";
        Raw($"verdict          : {verdict}");
        Raw($"log file         : {Path.GetFullPath(logPath)}");

        return anyWedge ? 1 : 0;

        // --- helpers ---------------------------------------------------------
        async Task<Dictionary<RioStatusType, int>> SnapshotStatusAsync()
        {
            // Two attempts: the first request can lose a race with the board's
            // post-DTR boot (port open pulses DTR = board reset), or get eaten
            // by a reply collision — seen on the 31250 bench run.
            for (int attempt = 0; ; attempt++)
            {
                lock (gate) { statusItems.Clear(); statusCollecting = true; }
                try
                {
                    await link.RequestVersionAsync();
                    await link.RequestCheckAsync();
                }
                catch { /* port trouble surfaces as an empty snapshot */ }
                await Task.Delay(1200);

                lock (gate)
                {
                    statusCollecting = false;
                    // Counters arrive one item per type; keep the last value per type.
                    var map = new Dictionary<RioStatusType, int>();
                    foreach (CheckStatus item in statusItems)
                        map[item.Type] = item.Number;
                    if (map.Count > 0 || attempt == 1)
                        return map;
                }
            }
        }

        static string FormatCounters(Dictionary<RioStatusType, int> c) =>
            c.Count == 0
                ? "(no status reply — reply path dead?)"
                : string.Join("  ", new[] { RioStatusType.RestartCount, RioStatusType.AbandonCount, RioStatusType.FullBufferCount }
                    .Select(t => $"{t}={(c.TryGetValue(t, out int v) ? v.ToString() : "-")}"))
                  + (c.ContainsKey(RioStatusType.BoardBad) || c.ContainsKey(RioStatusType.LampBad)
                      ? "  [board/lamp faults reported!]" : "");

        static string FormatDelta(Dictionary<RioStatusType, int> b, Dictionary<RioStatusType, int> a)
        {
            if (b.Count == 0 || a.Count == 0) return "(incomplete — a snapshot got no reply)";
            return string.Join("  ", new[] { RioStatusType.RestartCount, RioStatusType.AbandonCount, RioStatusType.FullBufferCount }
                .Select(t =>
                {
                    bool hb = b.TryGetValue(t, out int vb), ha = a.TryGetValue(t, out int va);
                    // 7-bit payload counters can wrap at 128.
                    return hb && ha ? $"{t}=+{(va - vb + 128) % 128}" : $"{t}=?";
                }));
        }
    }
}