CydandClaude Fable 5
1156eb8fe9
On a wedged (fully silent) board the receive loop sits in a pending net48 serial read that ignores cancellation; awaiting the link before closing the port hangs the tool at run end and loses the summary - exactly what happened on the first real baseline run (the board wedged at 0.62s and stayed dead, so no byte ever completed the read). Close the port first (same order RioCoordinator.Teardown uses); applies to both monitor and --mash modes. Selftest unaffected (its fake transport honors cancellation, which is why it never caught this). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
373 lines
17 KiB
C#
373 lines
17 KiB
C#
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 >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);
|
|
|
|
// --- 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("");
|
|
|
|
// --- wedge watchdog + progress ticker ----------------------------------
|
|
TimeSpan runEnd = sw.Elapsed + TimeSpan.FromSeconds(seconds);
|
|
TimeSpan nextProgress = sw.Elapsed + TimeSpan.FromSeconds(30);
|
|
while (sw.Elapsed < runEnd)
|
|
{
|
|
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}");
|
|
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()
|
|
{
|
|
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;
|
|
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}=?";
|
|
}));
|
|
}
|
|
}
|
|
}
|