using System.Diagnostics; using RioJoy.Core.Mapping; using RioJoy.Core.Protocol; using RioJoy.Core.Serial; namespace RioSerialMonitor; /// /// 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 >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. /// 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 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(); 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(); bool statusCollecting = false; var statusItems = new List(); 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 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 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} (command resends NAK/timeout: {link.Retransmits})"); 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> 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(); foreach (CheckStatus item in statusItems) map[item.Type] = item.Number; if (map.Count > 0 || attempt == 1) return map; } } } static string FormatCounters(Dictionary 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 b, Dictionary 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}=?"; })); } } }