ScadaBridge/docs/plans/2026-09-09-flow-debugger-step-logs-design.md

# Flow Debugger — Step Logs and Exceptions (design)

**Date:** 2026-09-09
**Status:** implemented 2026-09-09 (plan `2026-09-09-flow-debugger-step-logs.md`, 15 tasks). Deltas between this design and what shipped are marked *as built* in place.
**Extends:** `2026-09-05-flow-debugger-design.md` (§5 trace model, §7 central components), `2026-09-06-flow-debugger-outbound-calls.md` (folded nodes), register row 110 (console capture on `ScriptRun`)
**Mockup:** `docs/plans/2026-09-09-flow-debugger-step-logs-mockup.html` (published as a Claude artifact — link in the session recap)

## 1. What changes

A traced Flow Debugger run shows, **on the node that produced them**:

1. **The exception a failing step threw** — type, message, stack, inner exception — not just the one-line
   `Script 'X' on instance 'Y' failed: …` summary the `ScriptRun` row carries today.
2. **Log lines** — a new `Log` global every script surface exposes (`Log.Debug/Info/Warn/Error(message,
   exception?)`), plus the warnings the runtime logs on the script's behalf while a helper step runs.

Rendering: a per-level count badge in the node footer; a failed node's subtitle becomes `ExceptionType:
message`; a **Log** tab in the detail panel (exception block first, then the lines, `All | Warn +` filter,
copy); run-wide `n errors · n warnings · n info` in the status strip. Live and Replay read the same rows.

## 2. What exists (verified 2026-09-09)

- **Scripts cannot log.** `ScriptGlobals` (site) and `InboundScriptContext` (central) expose no `Log`,
  `Logger` or `ILogger`; the four script imports have no `Console`. `ScriptRuntimeContext._logger` and
  `_siteEventLogger` are private. So "logger messages" needs a new API surface, not a rewiring.
- **The failure row exists but lacks the detail.** `ScriptRunLauncher.RunScriptAsync` emits a Failed
  `ScriptRun` row on both catch paths (`ScriptRunLauncher.cs:458-506`) with `errorMessage` only;
  `errorDetail` is never passed (`:588`) although `ScadaBridgeAuditEventFactory.Create` accepts it and the
  DB helpers already fill it with `ex.ToString()`. `FlowStepProjector.Project` drops `AuditDetails.ErrorDetail`.
  Centrally, `InboundScriptExecutor.ExecuteAsync` swallows the exception into `"Internal script error"` /
  `SCRIPT_ERROR` (`InboundScriptExecutor.cs:548-552`) and the runner's inbound row gets that text.
- **No execution-id enrichment on node loggers.** Zero `LogContext.PushProperty` calls; `Enrich.FromLogContext`
  is not configured; the `TraceContextEnricher` stamps W3C ids only. `site_events` has no execution-id column.
  Capturing what *other* actors log for a run is therefore out of reach without a separate enrichment
  initiative (§9).
- **The plumbing to reuse:** `ScriptRuntimeContext.EmitTrace` (collector first, writer second, same
  `AuditEvent` both ways); `FlowTraceCollector` (500 events / 1 MB, redacted, `Complete()` at reply time);
  `RouteHelper.TraceSink` and the runner's central collector; `GetTraceEventsAsync` already returns every
  `ScriptTrace` row of the tree; `FlowGraphBuilder.Fold` already folds multi-row operations into one step;
  the Test Run sandbox already has a `ConsoleOutput` pane (`SandboxRunResult.ConsoleOutput`).

## 3. Decisions

| # | Decision | Rejected / why |
|---|----------|----------------|
| D1 | **A log line is an audit row:** new `AuditKind.ScriptLog` in channel `ScriptTrace` (appended last in the enum), one row per line, never a node — `FlowGraphBuilder` folds it into its owning step's new `Logs` list. | A side channel on the reply (`RouteToCallResponse.LogLines`) — Replay would have nothing; a second store to redact/retain/purge. Folding into the `ScriptRun` row's `Extra` (register row 110's sketch) — the 8 KB payload cap on that row would silently drop lines, and helper-step attribution would need every helper to buffer. |
| D2 | **Attribution is explicit.** `Extra.stepEventId` names the step; absent, the line belongs to the execution's **anchor** (site: the `ScriptRun` row of that `ExecutionId`; central: the `InboundRequest` row, or the debugger's synthesized `RouteCall` root for a script entry). No anchor and no matching step id → the first step of that execution; no step at all → dropped and counted (`FlowGraph.UnattachedLogLines`, shown in the strip). | Attribution by time window (`OccurredAtUtc` inside a step's `[start, start+duration]`) — step rows record different instants per kind and a 1 ms burst of writes makes it a coin toss. |
| D3 | **Exception detail rides `errorDetail`.** Site: `EmitScriptRun` passes `ex.ToString()` on the exception path (timeouts stay detail-less — an `OperationCanceledException` stack is noise). Central: `InboundScriptResult` gains an internal `ErrorDetail` (never returned to the HTTP caller); `FlowDebugRunner` puts it on the inbound row, and the HTTP path stashes it in `HttpContext.Items` for `AuditWriteMiddleware` so a `TraceAllCalls` Replay has it too. `FlowStep` gains `ErrorDetail`. | A separate `ScriptLog` row for the throw — duplicates the failure row and needs an ordering rule against it. |
| D4 | **`Log` global on every surface:** `ScriptGlobals.Log` and `InboundScriptContext.Log` at runtime; `ScriptCompileSurface.Log` (`CompileLog`) and `SandboxScriptHost.Log` / `SandboxInboundScriptHost.Log` for parity (the sandbox mirror appends to the Test Run `ConsoleOutput`). Signature `void Debug/Info/Warn/Error(string message, Exception? exception = null)`; synchronous; never throws into the script. `Log` is not on `ScriptTrustPolicy`'s deny list (it is a deny-list over API roots), pinned by a test that `Log.Info(...)` passes the gate and binds on all surfaces. | A `Console.WriteLine` shim — `Console` is not imported today and a stdout metaphor has no level. |
| D5 | **Untraced runs pay nothing.** `Log.*` always forwards to the node's `ILogger` (category `ScadaBridge.ScriptLog`, structured `Instance`/`Script`/`ExecutionId`/`Level`) and emits a `ScriptLog` row only when `_isTraced`. No site event. `TraceAllCalls` methods gain lines in Replay at ~1 row per line. | Always auditing lines (volume: timer/value-change scripts run at high rates). A no-op when untraced (authors would lose the messages they wrote). |
| D6 | **Runtime lines through one seam.** When traced, `ScriptRuntimeContext` wraps its `_logger` in a `TraceCapturingLogger` that forwards everything and copies **Information and above** into `ScriptLog` rows with `logSource = "runtime"`. Attribution uses an ambient `TraceStepScope` (`AsyncLocal<Guid?>`): the three attribute helpers (`SetAttribute`, `WriteBatchAndWait`, `WaitInternal`) and the sync `ExternalSystem.Call` pre-mint their step's `EventId`, open the scope for their body, and pass the id to `EmitTrace` (new optional `eventId` parameter). Everything else falls back to the anchor (D2). The launcher's own `LogError` for the run's exception is **not** captured as a line — it is already the exception block (D3). | Editing every `_logger.LogWarning` call site to also emit a row. Capturing Debug (internal chatter). |
| D7 | **Bounded.** `MaxLogLinesPerRun` (default 200; `SiteRuntimeOptions` + `InboundApiOptions`, validated `> 0`) and a 2 000-char message cap at the API; past the line cap, lines are dropped and one closing runtime `warn` row names the dropped count at run end. Inline, `ScriptLog` rows ride the collector's low-priority lane — as built that is an optional parameter on the existing method, `FlowTraceCollector.Add(evt, lowPriority: true)`, not a fourth public `AddLowPriority` method (Commons keeps its public method count tight, and every caller already had the event in hand): they stop at `max − 50` events / 75 % of the byte budget so the step rows emitted at run end (the `ScriptRun` anchor is written **last**) are never crowded out; a dropped low-priority row sets `LogsTruncated`, surfaced separately from `Truncated` (see §7 for the shipped wording). | Raising the collector cap (the reply also carries the return value under the 4 MB gRPC limit). |
| D8 | **UI rules.** Badge: highest severity first, `✕ n` danger, `! n` warn, `≡ n` faint; hidden when no lines. Failed subtitle: `Type: message` (type without namespace). Detail: **Log (n)** tab after Output; a step with an exception opens on Log, every other step on Input; the Output tab's existing alert stays and links to Log. Strip: `Log: n errors · n warnings · n info` counting lines, not steps. Ordering inside a step: `(OccurredAtUtc, Extra.seq)` — one clock per execution, `seq` breaks same-ms ties. | Drawing lines as nodes (a 40-line script would be unreadable). |
| D9 | **Replay and CLI.** `GetTraceEventsAsync` needs no change (channel filter already includes all of `ScriptTrace`). CLI `flow-debug run-*|replay` table gains a `logs` column (count) and `--show-logs` prints lines indented under their step. | — |

## 4. Trace model (additive)

`ScriptLog` row: `OccurredAtUtc` = line time; `Status = Delivered`; `Target` = script name (as `ScriptRun`);
`RequestSummary` = message; `ErrorMessage` / `ErrorDetail` = the attached exception's message / `ToString()`;
`ExecutionId` / `ParentExecutionId` / `SourceSiteId` / `SourceInstanceId` / `SourceNode` as the run's other
rows. `ScriptTraceExtra` gains `LogLevel` (`debug|info|warn|error`), `LogSource` (`script|runtime`),
`StepEventId` (`Guid?`), `Seq` (`int?`). Redaction (payload caps, header/body regexes) applies unchanged;
`AuditLog:PerChannelRetentionDays:ScriptTrace` covers the new kind.

`FlowStep` gains `ErrorDetail` (`string?`) and `Logs` (`IReadOnlyList<FlowLogLine>?`);
`FlowLogLine(EventId, ExecutionId, OccurredAtUtc, Level, Source, Message, ExceptionMessage,
ExceptionDetail, StepEventId, Seq)` — as built, the line keeps its own `ExecutionId` (so a folded
step can say which execution a line came from, and the cross-step hint can name it) plus the
attribution inputs `StepEventId` and `Seq` that `FlowGraphBuilder` sorted by, rather than discarding
them at projection time. `FlowGraph` gains `LogsTruncated` (`bool`) and `UnattachedLogLines`
(`int`). None of this is on the wire.

**Mixed versions.** An OLD central ingesting `ScriptLog` rows from a NEW site projects them to
`FlowStepKind.Unknown` **nodes** (the projector renders unknown kinds rather than dropping them) — the
existing rule *upgrade central first* covers it. An old site sends no lines; the page is unchanged.

## 5. Site runtime

- `ScriptLogger` (`SiteRuntime/Scripts/`), created by `ScriptRuntimeContext` and exposed as `Log`; holds the
  context's `EmitTrace` delegate, the `ILogger`, the caps and a per-run counter (`CallShared` shares the
  context, so inline shared scripts share the counter and the anchor).
- `EmitTrace(kind, …, eventId: Guid? = null)`; `TraceStepScope.Current` (`AsyncLocal<Guid?>`) read when
  building a `ScriptLog` row and no explicit step id is given.
- `TraceCapturingLogger : ILogger` — decorator installed only when `_isTraced`; `IsEnabled` delegates to the
  inner logger OR `level >= Information`, so a node whose Serilog minimum is Warning still captures
  Information lines into the trace (they are trace data, not node log output).
- `ScriptRunLauncher`: pass `errorDetail: ex.ToString()` on the exception path; before `collector?.Complete()`
  ask the context to flush its "dropped lines" closing row.

## 6. Central

- `InboundScriptContext.Log` → `InboundScriptLogger` writing through the executor's existing inline sink
  (`route.TraceSink`) and `ICentralAuditWriter` when traced (`InboundScriptExecutor.ExecuteAsync(...,
  trace)` already knows); ILogger always.
- `InboundScriptResult` `+ string? ErrorDetail` (positional-last, default null). `FlowDebugRunner` inbound row
  `errorDetail: result.ErrorDetail`. `EndpointExtensions` (the `executor.ExecuteAsync` call site, `:276`) → `HttpContext.Items[AuditErrorDetailKey]` →
  `AuditWriteMiddleware` `errorDetail:` (the HTTP body stays `SCRIPT_ERROR`).
- `FlowGraphBuilder`: partition `ScriptLog` rows out before `Fold`, attach per D2 after the steps list is
  final (a folded outbound step's `EventId` is its first row's, so `stepEventId` must be the pre-minted
  first-row id — only the sync helpers pre-mint in v1, which is exactly the set D6 scopes).

## 7. Central UI

`FlowGraphView`: footer becomes a flex row (subtitle + badge); `NodeClass` unchanged; `data-test="flow-node-logs"`.
`FlowStepDetail`: `Log` tab (`data-test="flow-step-tab-log"`), exception block (`flow-step-exception`), line
table (`flow-step-log-lines`), level filter, copy (JS interop `navigator.clipboard`, loose in bUnit), the
cross-step hint ("n more on <step>" selects that step via a new `OnSelectStep` callback).
`FlowDebugger`: strip counts (`flow-log-counts`, `Log: n errors · n warnings · n info`, counting
LINES not steps), the `flow-logs-truncated` badge and the `flow-unattached-logs` note; `ApplyOutcome`
unchanged (a run with only warning lines is still Completed).

**Truncation badge wording and its clearing rule.** The badge reads **"inline log lines capped —
refresh outcomes pulls the rest"**: it is a *this-copy-is-short* notice with the remedy in it, not a
data-loss warning — the rows exist in full in the audit store, and Replay reads them all. It is
driven by `FlowGraph.LogsTruncated`, which the page recomputes from the rows it currently holds, so
a *Refresh outcomes* that merges in more log rows **clears the badge on its own**; it must never be
latched on the run. (Contrast `Truncated`, the event-list cap, which is a property of the Live reply
itself.)

## 8. Security

Log messages are script-authored text and pass the same `IAuditRedactor` as every other summary (secrets in
a `Log.Info($"token={t}")` are scrubbed by the body regexes where they match, and the 8 KB cap applies).
Exception detail can carry connection strings in `ex.Message` for DB helpers — the DB helpers already
store `ex.ToString()` in `errorDetail` today, so no new exposure class; the redactor's error-row cap (64 KB)
bounds it. Nothing new crosses the PSK boundary: `ScriptLog` rows ride the existing `AuditEventDto`.

## 9. Out of scope (recorded)

Live streaming of lines during a long run (rows still arrive with the reply — D4 of the base design);
a run-wide chronological log list (belongs to the Direction B list, register row 110); capturing what
**other actors** log for a run (instance actor, DCL) — needs `LogContext` enrichment with `ExecutionId` plus
`Enrich.FromLogContext()` and an execution-id column on `site_events`; a `Log` sink to the site event log; capturing `Console.Out` on a site run — `System` is imported so
`Console.WriteLine` compiles today, and the Test Run sandbox captures it (`SandboxConsoleCapture`), but on a
site node `Console.Out` is process-global and shared by every concurrent run, so per-run capture is unsound;
`Log.*` is the leveled, per-run replacement and the sandbox mirror writes to the same console pane.

## 10. Testing

Pure: `FlowGraphBuilderTests` (attachment by step id, anchor fallback, first-step fallback, unattached count,
ordering by seq, folded-step attachment), `FlowStepProjectorTests` (`ErrorDetail`, `ScriptLog` never a node),
`FlowTraceCollectorTests` (low-priority reserve, `LogsTruncated`). Site: `ScriptLoggerTests` (levels, caps,
closing row, untraced = ILogger only), `TraceCapturingLoggerTests`, `ScriptRuntimeContext` scope attribution,
`ScriptRunLauncher` `errorDetail`. Central: executor `ErrorDetail`, runner inbound row, middleware item key,
`InboundScriptContext.Log` traced/untraced. Trust: `Log.*` passes the gate and binds on all four surfaces.
UI (bUnit): badge, failed subtitle, Log tab default, filter, cross-step hint, strip counts. Rig:
`verify-delmia-notifier.sh` step **J** — a seeded `FlowLogDemo` script logs three levels and throws;
Live shows the exception on the script node and the lines on their steps; Replay matches.

## 11. Documents to update

`Component-CentralUI.md` (Flow Debugger bullet), `Component-SiteRuntime.md` (`Log` global, caps, capturing
logger), `Component-InboundAPI.md` (`Log`, `ErrorDetail`), `Component-AuditLog.md` (`ScriptLog` kind),
`Component-ScriptAnalysis.md` (compile surface), CLI README (`--show-logs`), `CLAUDE.md` Flow Debugger bullet
(v1.4), deferred-work register row 110 (close the console half; keep Direction B), plus a new row for the
node-logger enrichment follow-up (§9).