fix(flow-debugger): review follow-ups — redact runner-synthesized rows, spawner rule, budget doc, CLI ceiling note (arch-review remediation)

Code review of the merged arch-review remediation (Tasks 1-13) found four items.

1. FlowDebugRunner returned its OWN synthesized rows un-redacted. RunMethodAsync's
   inbound row and RunValueChangeAsync's root row were handed to WriteCentralAsync
   (whose writer redacts a private copy) and then put RAW into the returned Events —
   so a Live run's caller saw the unfiltered row while Replay of the same execution
   showed the redacted one, defeating F1's "Live shows what Replay reads back". Both
   methods now resolve IAuditRedactor once per run and place the filtered copy into
   the result (including the early-return path on a failed attribute write); the raw
   row still reaches the writer, which redacts itself.

2. FlowGraphBuilder's spawner search degenerated to "the last step of the parent".
   Since executions are ordered as contiguous blocks, position[p] < childPosition
   holds for EVERY parent step, so a run shaped ScriptRun -> Write(A) -> Wait ->
   Write(B) whose Write(A) fired the cascade drew the Spawn edge from Write(B). New
   rule, in order: (a) the last non-async, non-Response parent step occurring at or
   before the child's first step — parent and child of a trigger cascade share the
   site clock, so this picks the write that actually fired it; (b) the position rule
   as fallback, which is the mixed-clock case F5 was written for (a child clock
   behind its parent's, where no parent step satisfies (a)); (c) parentChain[0].
   The class remark's stale "Replay order is unchanged" claim is replaced with what
   actually happens to a central Database.* call made after Route.To().Call.

3. FlowTraceCollector's byte budget counts UTF-16 chars of DetailsJson only, so
   "well under the 4 MB gRPC default" overstated it. Documented honestly: ~1 MB of
   UTF-8 for ASCII payloads, ~3 MB worst case for non-ASCII, both under 4 MB before
   framing — and raise it only against a real serialized-size measurement.

4. CLI --timeout-seconds help + README row now say the management endpoint caps
   flow-debug run-method at ManagementService:LongRunningCommandTimeout (default
   5 min), so a larger client value still 504s at the server's ceiling.

Deferred-work register rows 112 (site-side inline trace truncation is invisible to
the operator — needs a proto field) and 113 (the F2 method-entry site scope gates
routed traffic only; ApiMethods have no site affinity to scope against) record what
this review deliberately did not fix.

Tests: FlowGraphBuilderTests gains the same-clock Write(A)/Wait/Write(B) cascade
(red before the rule change, and the clock-behind test still passes on rule (b));
FlowDebugRunnerTests extends the redactor test to the inbound row and adds two
value-change cases (settled poll, failed write). Commons 793, ManagementService 615,
CentralUI 1264, CLI 462 — all green.

Claude-Session: https://claude.ai/code/session_01NcMG6xXdsJbmD2wYAgkK29
This commit is contained in:
Joseph Doherty
2026-09-06 14:44:34 -04:00
parent 6c9ea39f12
commit f17bae093a
8 changed files with 120 additions and 14 deletions
@@ -44,7 +44,9 @@ public static class FlowDebugCommands
var paramsOption = new Option<string?>("--params") { Description = "Flat JSON object of method parameters (validated against the method's schema)" };
var timeoutOption = new Option<int>("--timeout-seconds")
{
Description = "Client-side wait for the run; set to the method's TimeoutSeconds + 25 for long methods",
Description = "Client-side wait for the run; set to the method's TimeoutSeconds + 25 for long methods. "
+ "The server caps long-running commands at its own ManagementService:LongRunningCommandTimeout "
+ "(default 5 min), so a larger value still 504s at that ceiling",
DefaultValueFactory = _ => 120,
};
var cmd = new Command("run-method") { Description = "Run an inbound API method on the active central node with full tracing and print the flow's steps" };
+1 -1
View File
@@ -2312,7 +2312,7 @@ scadabridge --url <url> flow-debug run-method --method-id <int> [--params <json>
|--------|----------|-------------|
| `--method-id` | yes | Inbound API method ID (`api-method list`) |
| `--params` | no | Flat JSON object of parameters, validated against the method's parameter schema. Omit for a parameterless method. |
| `--timeout-seconds` | no | Client-side wait for the run (default 120). Raise this above the method's own `TimeoutSeconds + 25` for a long-running method, or the client gives up before the server's own run grace does. |
| `--timeout-seconds` | no | Client-side wait for the run (default 120). Raise this above the method's own `TimeoutSeconds + 25` for a long-running method, or the client gives up before the server's own run grace does. **Server ceiling:** the management endpoint applies `ScadaBridge:ManagementService:LongRunningCommandTimeout` (default 5 min) to `flow-debug run-method`, so a value above that still returns `504` at the server's ceiling — raise the server setting too if a method legitimately runs longer. |
Parameters that fail schema validation are reported as `VALIDATION_FAILED` without running
the script.
@@ -19,15 +19,22 @@ namespace ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging;
/// <item><b>Order</b> = emission order between executions, timestamp within one (arch-review F5: central and
/// site clocks differ). Executions are ordered by the input index of their earliest-given row; inside one
/// execution — one clock — steps are ordered by <c>OccurredAtUtc</c>, then a kind rank (inbound before route
/// call before script run before writes/waits before outbound), then the input index. Replay input arrives
/// timestamp-sorted from the repository, so its order is unchanged; the Live path's collector order wins.</item>
/// call before script run before writes/waits before outbound), then the input index. Replay input is
/// timestamp-sorted; executions are still grouped into contiguous blocks ordered by their first row, so a
/// root-execution step that ran after a routed call (e.g. a central <c>Database.*</c> call after
/// <c>Route.To().Call</c>) displays before the routed site steps — display order only, edges are id-based.</item>
/// <item>Within one <c>ExecutionId</c> consecutive steps are chained in that order, <b>skipping async steps</b> — a
/// <c>Notify</c>, or a cached operation whose first row is <c>CachedSubmit</c>. Each skipped step instead gets an
/// <c>Async</c> (dashed) edge from the chain step immediately before it in time.</item>
/// <item>The first step of an execution is linked from its spawner: a <c>RouteCall</c> whose
/// <c>childExecutionId</c> matches, else the last step of the parent execution that precedes it in
/// the order above — that second case is a <c>Spawn</c> edge (trigger cascade). The edge
/// <c>CrossesBoundary</c> when exactly one end is in the Central lane.</item>
/// <c>childExecutionId</c> matches, else — a <c>Spawn</c> edge (trigger cascade) — the last non-async,
/// non-<c>Response</c> parent step that <b>occurred at or before</b> the child's first step. Parent and
/// child of a cascade share the site clock, so that timestamp rule picks the write that actually fired
/// the trigger; only when it finds nothing (a child clock BEHIND its parent's — a mixed-clock Replay)
/// does the search fall back to display position, and then to the parent's first step. Position alone
/// is not enough: executions are contiguous blocks, so every parent step precedes the child block and
/// the search would always land on the parent's LAST step. The edge <c>CrossesBoundary</c> when
/// exactly one end is in the Central lane.</item>
/// <item>An <c>AttributeWait</c> that was satisfied gets an <c>External</c> (dashed) edge from the
/// preceding <c>AttributeWrite</c> in the same execution — the device echo the system inferred.</item>
/// <item>When an <c>InboundRequest</c> row carries a response summary, a <c>Response</c> step is
@@ -132,9 +139,17 @@ public static class FlowGraphBuilder
spawner = routeCall;
else if (byExecution.TryGetValue(parentId, out var parentChain))
{
// The parent step that precedes the child in DISPLAY order, not by raw timestamp (F5).
// A trigger cascade's parent and child are both stamped by the SITE clock, so the step
// that fired it is the last eligible parent step at or before the child's first step.
// Display position cannot answer this: executions are contiguous blocks, so every parent
// step precedes the child and the position rule degenerates to "the parent's last step"
// (a run shaped ScriptRun → Write(A) → Wait → Write(B) would spawn from Write(B)).
// Position stays as the fallback for the mixed-clock case F5 was written for — a child
// clock behind its parent's, where no parent step satisfies the time rule.
var childTime = first.OccurredAtUtc;
var childPosition = position[first.EventId];
spawner = parentChain.LastOrDefault(p => position[p.EventId] < childPosition && p.Kind != FlowStepKind.Response && !IsAsync(p))
spawner = parentChain.LastOrDefault(p => Spawnable(p) && p.OccurredAtUtc <= childTime)
?? parentChain.LastOrDefault(p => Spawnable(p) && position[p.EventId] < childPosition)
?? parentChain[0];
}
@@ -205,6 +220,14 @@ public static class FlowGraphBuilder
return new FlowGraph(steps, edges, Predicted: false, Truncated: truncated);
}
/// <summary>
/// Can a step be the spawner of a cascaded child execution? The synthesized <c>Response</c> node is not
/// a real step, and an async step (a fire-and-forget notification / cached call) never blocks long
/// enough to be the thing that fired a trigger.
/// </summary>
private static bool Spawnable(FlowStep step)
=> step.Kind != FlowStepKind.Response && !IsAsync(step);
/// <summary>
/// A step the script did not wait for: a notification, or a cached operation — any API / DB step whose
/// first lifecycle row is not the sync one-shot kind (<c>ApiCall</c> / <c>DbWrite</c>), the same rule the
@@ -22,6 +22,11 @@ namespace ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging;
/// The copy is also capped by BYTES as well as by count, because it rides a gRPC reply whose
/// default 4 MB receive limit a few hundred large error rows would otherwise breach — and that
/// same reply carries the script's return value, so an oversized trace would fail a real call.
/// The budget is an approximation, not a wire measurement: it sums the UTF-16 <c>char</c> length
/// of <see cref="AuditEvent.DetailsJson"/> only, so it ignores the event's other fields and the
/// protobuf framing, and 1 048 576 chars is 1 MB of UTF-8 for ASCII payloads but up to ~3 MB for
/// non-ASCII ones. That worst case still fits the 4 MB limit with the rest of the reply, which is
/// what the budget exists to guarantee — raise it only with a real serialized-size measurement.
/// </summary>
public sealed class FlowTraceCollector
{
@@ -30,7 +35,8 @@ public sealed class FlowTraceCollector
/// <summary>
/// Default inline byte budget per run — the summed redacted <see cref="AuditEvent.DetailsJson"/>
/// length, well under the 4 MB gRPC default receive limit the reply must fit in.
/// length in UTF-16 chars (see the type remarks: ~1 MB of UTF-8 for ASCII payloads, ~3 MB worst
/// case for non-ASCII ones, both under the 4 MB gRPC default receive limit before framing).
/// </summary>
public const int DefaultMaxBytes = 1_048_576;
@@ -113,7 +113,11 @@ public sealed class FlowDebugRunner
}
var root = Guid.NewGuid();
var collector = new FlowTraceCollector(redactor: sp.GetService<IAuditRedactor>());
// One redactor for the whole run: the collector filters the emitted rows, and the runner
// filters the rows it synthesizes ITSELF (review follow-up) — the central writer redacts a
// private copy, so without this the caller's copy of the inbound row would be the raw one.
var redactor = sp.GetService<IAuditRedactor>();
var collector = new FlowTraceCollector(redactor: redactor);
var startedAt = DateTimeOffset.UtcNow;
var sw = Stopwatch.StartNew();
var timeout = TimeSpan.FromSeconds(Math.Max(1, method.TimeoutSeconds));
@@ -177,7 +181,7 @@ public sealed class FlowDebugRunner
// clock and site rows the site's, so re-sorting by OccurredAtUtc lets a skewed site clock float
// its steps ahead of the RouteCall that started them. (The value-change path below keeps its
// OrderBy: every row it merges was stamped by the same site.)
var ordered = new List<AuditEvent>(events.Count + 1) { inboundRow };
var ordered = new List<AuditEvent>(events.Count + 1) { redactor?.Apply(inboundRow) ?? inboundRow };
ordered.AddRange(events);
return new FlowDebugRunResult(
@@ -210,6 +214,9 @@ public sealed class FlowDebugRunner
var root = Guid.NewGuid();
var startedAt = DateTimeOffset.UtcNow;
var sw = Stopwatch.StartNew();
// Review follow-up: the root row is synthesized here, so the copy handed back must be
// redacted by this method — WriteCentralAsync's writer only redacts its own private copy.
var redactor = sp.GetService<IAuditRedactor>();
// IInstanceRouter is the same seam RouteHelper uses (central binds it to the comms layer).
var router = sp.GetRequiredService<IInstanceRouter>();
var write = await router.RouteToSetAttributesAsync(
@@ -239,11 +246,12 @@ public sealed class FlowDebugRunner
Writes = [new AttributeWriteDetail(cmd.AttributeName, cmd.Value, write.Success, write.ErrorMessage)],
}.ToJson());
await WriteCentralAsync(sp, rootRow, ct).ConfigureAwait(false);
var redactedRoot = redactor?.Apply(rootRow) ?? rootRow;
if (!write.Success)
{
return new FlowDebugRunResult(root, false, write.ErrorMessage ?? "Attribute write failed", "WRITE_FAILED",
[rootRow], false, startedAt, DateTimeOffset.UtcNow);
[redactedRoot], false, startedAt, DateTimeOffset.UtcNow);
}
// Poll the site for the traced run(s) the write spawned — matched by ParentExecutionId
@@ -281,7 +289,7 @@ public sealed class FlowDebugRunner
await _delay(PollInterval, ct).ConfigureAwait(false);
}
var ordered = new List<AuditEvent> { rootRow };
var ordered = new List<AuditEvent> { redactedRoot };
ordered.AddRange(known.Values.OrderBy(e => e.OccurredAtUtc).ThenBy(e => e.EventId));
var completed = known.Values.Any(e =>
{