From c810bd0f7c735689af96546ab279f3bd36d7fada Mon Sep 17 00:00:00 2001 From: Joseph Doherty Date: Tue, 10 Nov 2026 06:12:34 -0500 Subject: [PATCH] feat(logging): bridge Akka logging to Serilog and copy traced runs' node-log lines into the Flow Debugger (ScadaBridge#120, #56) #120: Akka ILoggingAdapter lines used to bypass Serilog and go to stdout only. - BuildHocon sets akka.loggers = [Host.Actors.SerilogAkkaLogger] and keeps akka.loglevel = INFO, so Akka Debug chatter is still filtered at the adapter. The INFO+ lines that used to reach stdout now go through the Serilog pipeline instead, with no extra volume. - Lines reach the file sinks with the node enrichers. SourceContext is the logging class's full name, AkkaSource is the actor path, Akka's own timestamp is kept, and format arguments become structured properties. - The Akka logger actor writes on its own thread, after the logging actor's LogContext is gone. To keep the ExecutionId, the two DCL actors log through ExecutionAwareLogging.GetLogger(Context), which records ExecutionLogContext.Current (a new AsyncLocal mirror of the pushed id) in an ExecutionTaggedLogMessage. The logger actor pushes that id again while it writes the line. #56 remainder (coordinator decision: no replicated schema change): - The host pipeline gains ExecutionLogCaptureSink. - While a run is traced, its step logger registers its ExecutionId: the site ScriptLogger from the launcher (plus each inline CallShared child id), and the central InboundScriptLogger from the executor. - Each tagged line becomes a ScriptLog row with LogSource "node" and the new ScriptTraceExtra.LogCategory. - The rows count against the existing MaxLogLinesPerRun cap, are clipped at 2 000 chars, ride the low-priority collector lane and pass the same redactor. Untraced runs cost one volatile read. - Lines are never copied twice. The step loggers' own forwards run inside ExecutionLogCapture.Suppress(), and the sink suppresses itself while it calls a target. The registration is declared inside the launcher's and executor's try, so it ends before the catch blocks log the outcome, and FlushDropped closes it. - FlowGraphBuilder lists node lines in FlowGraph.NodeLogs and never folds them onto a step. - The Flow Debugger shows them in a Node log card (FlowNodeLogPanel): grouped per execution under its run step, with an All | Warn + filter. Live and Replay both read the same rows, so site scope and role rules apply unchanged. - CLI --show-logs prints them as a trailing block. Tests: Commons ExecutionLogCaptureTests, ExecutionLogContext.Current, FlowGraphBuilder node lines. SiteRuntime NodeLogCaptureTests covers cross-actor capture via the launcher, untraced runs capturing nothing, no double capture of script and runtime lines or of the launcher failure line, the shared cap, collector redaction, shared-script child ids and FlushDropped closing capture. InboundNodeLogCaptureTests covers the central path. DCL ExecutionAwareLoggingTests covers the DataConnectionActor write-path Debug line being tagged and an uncorrelated line not being tagged. Host SerilogAkkaLoggerTests covers mapping, the ExecutionId crossing the logger hop, HOCON, ActorSystem boot and the Akka line reaching a traced run's step log end to end. Host LoggerConfigurationTests checks that the sink is wired. bUnit FlowNodeLogPanelTests and a CLI projection test cover the UI and CLI. Every new assertion was mutation-proven. Docs: step-logs design section 12, Component-SiteRuntime, CentralUI, InboundAPI, Host, CLI README, CLAUDE.md. Claude-Session: https://claude.ai/code/session_01GT67AEHd2Acv1YPwGfXEoV --- CLAUDE.md | 2 +- ...26-09-09-flow-debugger-step-logs-design.md | 53 ++- docs/requirements/Component-CentralUI.md | 2 +- docs/requirements/Component-Host.md | 2 + docs/requirements/Component-InboundAPI.md | 5 + docs/requirements/Component-SiteRuntime.md | 2 +- .../Commands/FlowDebugTableProjection.cs | 18 + src/ZB.MOM.WW.ScadaBridge.CLI/README.md | 13 +- .../Deployment/FlowNodeLogPanel.razor | 151 +++++++++ .../Pages/Deployment/FlowDebugger.razor | 5 + .../Observability/ExecutionLogCapture.cs | 216 ++++++++++++ .../Observability/ExecutionLogContext.cs | 42 ++- .../ExecutionTaggedLogMessage.cs | 27 ++ .../Types/Debugging/FlowGraph.cs | 8 +- .../Types/Debugging/FlowGraphBuilder.cs | 23 +- .../Types/Debugging/FlowStep.cs | 13 +- .../Types/Debugging/FlowStepProjector.cs | 3 +- .../Types/Debugging/ScriptTraceExtra.cs | 5 +- .../Actors/DataConnectionActor.cs | 7 +- .../Actors/DataConnectionManagerActor.cs | 7 +- .../Logging/ExecutionAwareLogging.cs | 95 ++++++ .../Actors/AkkaHostedService.cs | 8 + .../Actors/SerilogAkkaLogger.cs | 149 +++++++++ .../LoggerConfigurationFactory.cs | 7 +- .../InboundScriptExecutor.cs | 5 + .../InboundScriptLogger.cs | 105 +++++- .../Scripts/ScriptLogger.cs | 107 +++++- .../Scripts/ScriptRunLauncher.cs | 7 + .../Scripts/ScriptRunLogScope.cs | 3 +- .../Scripts/ScriptRuntimeContext.cs | 16 +- .../Scripts/TraceCapturingLogger.cs | 8 +- .../FlowDebugCommandsTests.cs | 38 +++ .../Deployment/FlowNodeLogPanelTests.cs | 103 ++++++ .../Debugging/FlowGraphBuilderLogLineTests.cs | 42 +++ .../Observability/ExecutionLogCaptureTests.cs | 148 +++++++++ .../Observability/ExecutionLogContextTests.cs | 25 ++ .../Actors/ExecutionAwareLoggingTests.cs | 131 ++++++++ .../LoggerConfigurationTests.cs | 28 ++ .../SerilogAkkaLoggerTests.cs | 231 +++++++++++++ .../InboundNodeLogCaptureTests.cs | 127 +++++++ .../Scripts/NodeLogCaptureTests.cs | 312 ++++++++++++++++++ .../Scripts/ScriptLoggerTests.cs | 6 +- .../Scripts/TraceCapturingLoggerTests.cs | 2 +- 43 files changed, 2261 insertions(+), 46 deletions(-) create mode 100644 src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Deployment/FlowNodeLogPanel.razor create mode 100644 src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogCapture.cs create mode 100644 src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionTaggedLogMessage.cs create mode 100644 src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Logging/ExecutionAwareLogging.cs create mode 100644 src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.CentralUI.Tests/Deployment/FlowNodeLogPanelTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogCaptureTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionAwareLoggingTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundNodeLogCaptureTests.cs create mode 100644 tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/NodeLogCaptureTests.cs diff --git a/CLAUDE.md b/CLAUDE.md index e17bfd4b..fb2ee32b 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -212,7 +212,7 @@ spec for each is `docs/requirements/Component-.md`, and `README.md` carrie - Central UI: Blazor Server (ASP.NET Core + SignalR) with Bootstrap CSS. No third-party component frameworks (no Blazorise, MudBlazor, Radzen, etc.). Build custom Blazor components for tables, grids, forms, etc. - UI design: Clean, corporate, internal-use aesthetic. Not flashy. Use the `frontend-design` skill when designing UI pages/components. - Debug view: real-time streaming via DebugStreamBridgeActor + gRPC (events via `SiteStreamGrpcClient`, snapshot via the `SiteCommandService` query surface — `QueryReply.DebugViewSnapshot`). Health dashboard: 10s polling timer. Deployment status: real-time push via SignalR. -- **Flow Debugger (2026-09-05, Deployment → `/deployment/flow-debugger` + CLI `flow-debug run-method|run-script|run-value-change|replay`).** Runs one entry point (an inbound API method, or a site script) and draws every step as a Central / Site / Tags / **External** swimlane; *Live* really runs it, *Replay* rebuilds a past execution. **v1.1 (2026-09-06, `docs/plans/2026-09-06-flow-debugger-outbound-calls.md`):** every `ExternalSystem.*` / `Database.*` / `Notify.Send` a traced run makes is an `ApiCall` / `DbCall` / `Notify` node on the External lane — the site routes those already-existing `ApiOutbound` / `DbOutbound` / `Notification` rows through the same inline trace collector, the replay query widens to those channels, and `FlowGraphBuilder` folds a cached operation's rows by `(kind, CorrelationId)` into ONE node with a `Lifecycle` (sync calls in-chain, cached/notify on dashed `Async` edges, trigger cascades on `Spawn` edges, the Response linked from the inbound execution's last step). Later lifecycle rows are not inline, so after a Live run the page polls the Replay command (5 s, ≤ 2 min) while any node is `Pending`, plus a *Refresh outcomes* button. **A refresh MERGES, never replaces (2026-09-06, found live in the browser):** the page unions the re-read rows into the run's own rows by `EventId` and rebuilds the graph, because a Live run carries its site rows inline while the same rows reach central's audit store by telemetry ~5–30 s later — a Replay read taken in between lacks them, and the old wholesale swap made an already-drawn node (a resolved cached DB write) vanish until the next manual refresh. The inline rows ARE the audited rows (`FlowTraceCollector` sinks the same `AuditEvent` objects the site writer persists), so the union is exact. Central method-script `Database.*` calls (`InboundDatabaseHelper`) are now audited (`DbOutbound`/`DbWrite`) — they were not. Rig demo: `docker/seed-flow-outbound-demo.sh` + `verify-delmia-notifier.sh` step I. **Trace steps ARE audit events** — `AuditChannel.ScriptTrace` with kinds `RouteCall` (central, **always-on** per `Route.To().Call`, joins the two halves of a Replay) and `ScriptRun` / `AttributeWrite` / `AttributeWait` (site, **gated** by a `bool Trace` riding beside `ParentExecutionId` on `RouteToCallRequest` / `ScriptCallRequest` / `SetStaticAttributeCommand` / `AttributeValueChanged`; proto fields additive, `site_command.proto` imports `sitestream.proto`). A Live run gets the site rows **inline** on `RouteToCallResponse.TraceEvents` (+ `ChildExecutionId`) because the 5 s telemetry cadence is too slow; Replay reads them from `AuditLog` (`GetTraceEventsAsync`). A value-change on a data-sourced attribute is a REAL tag write; the Instance Actor's **trace arm** (`SiteRuntime:TraceArmWindowSeconds`, 30) stamps the device echo with the writer's execution id so the triggered run is parented and traced, and central polls the site's new `PullTraceEvents` RPC (point read, not reconciliation) for it. Execution path is four management commands on the **per-node `ManagementActor`** (`FlowDebug*`; the three run commands are Deployer-only, Replay is wider) — a standby refuses the three run commands with **`STANDBY_NODE`** (shown verbatim); `ApiMethod.TraceAllCalls` (migration `AddApiMethodTraceAllCalls`, CLI `--trace-all-calls`) traces every real call to a method for later Replay (7–10 rows/call). Prediction before a run is a Roslyn syntax walk (`FlowShapePredictor`, REQ-SA-7, DB-free); the graph (`FlowStep`/`FlowGraphBuilder`, Commons) is a central projection, never a wire type; the renderer is custom SVG (`FlowGraphView`). Rig: `AuditLog:PerChannelRetentionDays:ScriptTrace=30` on both centrals; `verify-delmia-notifier.sh` step H proves live + replay. **Mixed-version caveat:** an older site ignores the flag → central `RouteCall` only, page says *site not traced*. **v1.2 (2026-09-06, `docs/plans/2026-09-06-flow-debugger-followups.md`):** a `Parked` External node offers **Retry / Discard in place** (same site-scope check, confirm and relay as the report pages, via `IFlowDebugService.RetryOutboundAsync`/`DiscardOutboundAsync`, then the page re-polls Replay until the node leaves Parked) and every folded node deep-links to `/site-calls/report?correlationId=` / `/notifications/report?correlationId=` (both pages accept it through additive `TrackedOperationIdFilter` / `NotificationIdFilter` query params and auto-open the row); register row 111 closed. **Trap closed the same day:** `FlowDebugService.PredictMethodAsync` used to resolve route targets with `GetAwaiter().GetResult()` inside the synchronous predictor walk — on the Blazor renderer sync context that DEADLOCKED the whole circuit (page inert, healthy websocket, no error) whenever a method routing to a site script was chosen; now a resolve-and-rewalk loop, pinned by a single-thread-pump test. Never block on a task from a Blazor event/lifecycle path. Browser checks of the page go through Playwright (`FlowDebuggerTests`, fixture login + an ephemeral method), not the login-disabled override. **Arch-reviewed 2026-09-06** (`docs/plans/2026-09-06-flow-debugger-arch-review.md`, remediation `docs/plans/2026-09-06-flow-debugger-arch-review-remediation.md`): the inline Live trace copy is now redacted and capped by the shared `FlowTraceCollector` (500 events **and** 1 MB of `DetailsJson`, F1), a method-entry Live run enforces the operator's site scope at route time (`RouteHelper.WithSiteScope` → `SITE_SCOPE_DENIED` → `ManagementUnauthorized`, F2) — **and since Gitea #55 a site-scoped operator is refused a method Live run outright** (a method has no site, so its central-side effects can't be scoped; audited, page disables the entry; Replay + script entry unchanged), and the page/Replay opened to the `OperationalAudit` roles under the new `RequireFlowDebugger` policy while everything that executes stays Deployer-only (F3). Design `docs/plans/2026-09-05-flow-debugger-design.md`; plan `docs/plans/2026-09-05-flow-debugger.md`. **v1.3 (2026-09-08, `docs/plans/2026-09-08-flow-debugger-script-entry-design.md`):** the second entry point is site → instance → **script**; ValueChange/Conditional scripts are fired by writing the trigger's attribute (derived from the trigger config, not picked), every other kind is a direct traced `RouteToCall` with a `ParameterValueForm` from the script's `ParameterDefinitions` and one operator-attributed `RouteCall` root row (`FlowDebugRunScriptCommand`, Deployer-only, long-running); `run-value-change` stays as the attribute-level CLI escape hatch (fires Expression triggers). **Instance picker (2026-09-08, `docs/plans/2026-09-08-instance-picker-design.md`):** Flow Debugger and Debug View both replaced their flat instance `` with the shared **`InstancePicker`** combobox — a text field whose dropdown is the site's area tree (`InstanceTreeBuilder`, all areas collapsed on open), typed text filters and expands to the matches; `Areas`/`Instances` are compared by reference, so callers must assign the loaded lists once per site change, never per render, or the panel closes on every re-render. **v1.4 (2026-09-09, `docs/plans/2026-09-09-flow-debugger-step-logs-design.md`):** scripts can log — a `Log.Debug/Info/Warn/Error(message, exception?)` global on all four surfaces (site `ScriptGlobals`, inbound `InboundScriptContext`, the `ScriptCompileSurface` deploy gate as `CompileLog`, and both Test Run sandboxes/editor hosts, where it appends to the console pane), always reaching the node `ILogger` and emitting a `ScriptTrace`/**`ScriptLog`** audit row (one per line) **only when the run is traced**, so an untraced timer script costs no audit volume. `FlowGraphBuilder` **folds those rows onto the step that produced them** (`FlowStep.Logs`) and never draws them as nodes — attribution is `Extra.stepEventId`, pre-minted by `SetAttribute`/`WriteBatchAndWait`/`WaitInternal`/sync `ExternalSystem.Call` through an `AsyncLocal` `TraceStepScope`, else the execution's anchor row, else its first step, else `FlowGraph.UnattachedLogLines`; the runtime's own Information+ entries are captured for free by a `TraceCapturingLogger` decorator instead of editing every `_logger.LogWarning` call site. The failing step now carries the **whole exception** (`errorDetail = ex.ToString()` on the site `ScriptRun` row and on the central inbound row — the latter never on the HTTP body, which stays `SCRIPT_ERROR`). **The two halves are NOT gated alike:** the central inbound row's `errorDetail` is stamped on **every failing method request, traced or not** (`EndpointExtensions` stashes it on `HttpContext.Items`, `AuditWriteMiddleware` consumes it), bounded only by the redactor's `ApiInbound` cap `AuditLog:InboundMaxBytes` (1 MiB default; the 64 KB `ErrorCapBytes` is what bounds every OTHER channel's error rows, the site `ScriptRun` row included) — tracing only decides whether the row is later readable as a Flow Debugger step; the site `ScriptRun` `errorDetail` is **traced-only**, because an untraced run emits no `ScriptTrace` row at all, rendered as a red `Type: message` subtitle plus a **Log (n)** tab; the node badge is `✕ n ! n ≡ n` and the strip counts `Log: n errors · n warnings · n info` (a `Log.Error` is a line, not a failed step — it never moves the state chip). Bounded: `ScadaBridge:SiteRuntime:MaxLogLinesPerRun` / `ScadaBridge:InboundApi:MaxLogLinesPerRun` (200, validated > 0), 2 000-char messages, one closing `warn`/`runtime` row naming the dropped count, and a **low-priority inline lane** (`FlowTraceCollector.Add(evt, lowPriority: true)`, log rows stop 50 events short of the count cap and at 75 % of the byte budget, reserving the rest for the step rows written at run end) whose overflow sets `LogsTruncated` → the page badge *inline log lines capped — refresh outcomes pulls the rest*, which clears once a refresh merges in more log rows. **"Never `await` an audit write on a script path" still holds** — every log row is enqueued fire-and-continue, exactly like the 2026-09-06 cached-call telemetry fix. **Trap:** build `ScriptLogger` over the UNDECORATED logger — `TraceCapturingLogger` refuses to wrap another `TraceCapturingLogger` (it would emit two rows per line). CLI `flow-debug … --show-logs` + a `logs` column; rig demo `docker/seed-flow-log-demo.sh` + `verify-delmia-notifier.sh` step J. Mixed-version: an OLD central projects a NEW site's `ScriptLog` rows as `Unknown` nodes — upgrade central first, as always. **Node log (2026-11-10, Gitea #56 + #120, step-logs design §12):** while a run is traced, other actors' node-log lines tagged with its `ExecutionId` (Instance Actor, DCL actors, adapters; central callees) are copied into its `ScriptLog` rows as source `node` by the host's `ExecutionLogCaptureSink`, with no `site_events` schema change. They share the run's line cap and redaction. Untraced runs cost one volatile read. They are listed per execution in a **Node log** card (`FlowGraph.NodeLogs`), never folded onto a step. Akka `ILoggingAdapter` lines now reach Serilog via `akka.loggers = [SerilogAkkaLogger]` (loglevel stays INFO). The DCL actors use `ExecutionAwareLogging.GetLogger(Context)` so their Akka lines keep the id across the logger-actor hop. **Traps:** the step loggers' own forwards run inside `ExecutionLogCapture.Suppress()`, which is per thread, so the sink must never sit behind an async wrapper. The capture registration is declared inside the launcher/executor `try` so it ends before the catch blocks log the outcome. **Method pane structured inputs (2026-09-10, Gitea #37, `docs/plans/2026-09-10-flow-debugger-method-params-design.md`):** the *Run inbound API method* pane now renders the same `ParameterValueForm` as the script pane (keyed on the method id) plus a **Form | Raw JSON** whole-payload escape hatch (Monaco, schema-validated on every edit); the page keeps ONE value tree and serializes it as-is, the old per-field text coercion is gone, and Run is disabled while the form or the raw document is invalid — so a required array-of-object parameter (MesMoveOut `WorkOrders`) can be entered, and a failed parse is never sent as a string. The per-method `localStorage` entry stores the value tree and is dropped on restore if it no longer validates (that also retires the pre-#37 flat string entries). - Health reports: 30s interval, 60s offline threshold, monotonic sequence numbers, raw error counts per interval. - Dead letter monitoring as a health metric. - Site Event Logging: 30-day retention, 1GB storage cap, daily purge, paginated queries with keyword search (keyword searches are clamped to `ScadaBridge:SiteEventLog:KeywordSearchMaxWindow`, 7 d; reads run off the writer lock on their own connection). **The cap measures `site_events` + its four indexes, NOT the consolidated LocalDb file** (register row 81, 2026-08-17): whole-file measurement made the trim unwinnable on a replicated node — each batch freed event pages while adding an equal count of oplog rows + tombstones to the same file, so it stopped 2.5x over a 64 MB cap and a node with a down peer could not enforce the cap at all. `dbstat` (the exact per-table measurement) is **NOT compiled into the bundled `SQLitePCLRaw.lib.e_sqlite3`** — probed and pinned by `SqliteCapabilityTests`, so don't reach for it — the footprint is modelled from sampled row width instead (−0.8%…+12.8%, biased high). Consequence: `MaxStorageMb` no longer bounds the data volume alone; LocalDb bookkeeping is separate overhead bounded by `MaxOplogRows`/`TombstoneRetention` and is deliberately not this component's job. The cap trim re-reads the footprint count on batch 1 then every `CapTrimCountRefreshBatches` (10th) batch and vacuums once per tick. Decision: `docs/plans/2026-08-17-site-event-log-cap-semantics-decision.md`. diff --git a/docs/plans/2026-09-09-flow-debugger-step-logs-design.md b/docs/plans/2026-09-09-flow-debugger-step-logs-design.md index 58730765..b9e7f84f 100644 --- a/docs/plans/2026-09-09-flow-debugger-step-logs-design.md +++ b/docs/plans/2026-09-09-flow-debugger-step-logs-design.md @@ -138,10 +138,10 @@ writer is *inferred* by the trace arm), `ScriptCallRequest`, the four `RouteTo*R `SourceExecutionId` — `GetAttributeRequest`, `WaitForAttributeRequest`, `WriteAttributeBatchRequest`, `WriteTagRequest`, `WriteTagBatchRequest`; the Instance, Script, Alarm, Deployment Manager and both DCL actors re-push it per message in `AroundReceive` (`ExecutionLogContext.PushFor`; one type test for an uncorrelated message). So a node-log line the Instance -Actor or a protocol adapter writes while serving a run's write carries the run's id. **Still open:** a queryable per-execution -sink — the `site_events` execution-id column (replicated table, both-nodes-together schema change) or a sink that copies tagged -lines of a *traced* execution into `ScriptLog` rows — and a Flow Debugger section that shows them; and the DCL actors' own Akka -`ILoggingAdapter` lines, which bypass Serilog entirely (Gitea #120); a `Log` sink to the site event log; capturing `Console.Out` on a site run — `System` is imported so +Actor or a protocol adapter writes while serving a run's write carries the run's id. **Capture done too — see §12** (no +`site_events` schema change: a Serilog sink copies the tagged lines of a *traced* execution into its `ScriptLog` rows, and the +Flow Debugger lists them in a *Node log* section); the DCL actors' own Akka `ILoggingAdapter` lines now reach Serilog with the +id (Gitea #120, §12). Still out of scope: 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. @@ -165,3 +165,48 @@ logger), `Component-InboundAPI.md` (`Log`, `ErrorDetail`), `Component-AuditLog.m `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). + +## 12. Other actors' lines per execution (Gitea #120 + #56, 2026-11-10) + +**Akka logging is bridged to Serilog (#120).** `AkkaHostedService.BuildHocon` sets +`akka.loggers = [SerilogAkkaLogger]` (Host) and keeps `akka.loglevel = INFO`, replacing Akka's stdout-only +`DefaultLogger`: every `ILoggingAdapter` line now reaches the file sinks with the node enrichers, as +`SourceContext` = the logging class's full name plus `AkkaSource` = the actor path, at the timestamp Akka +recorded, with the adapter's format arguments as structured properties. Akka's Debug chatter is still +filtered at the adapter, so the bridge adds no volume: the INFO+ lines that used to go to stdout only now go to +the Serilog sinks instead. Akka writes each line later on its logger actor's thread, where the logging actor's +`LogContext` no longer applies. The two DCL actors therefore log through +`DataConnectionLayer.Logging.ExecutionAwareLogging.GetLogger(Context)`, which records +`ExecutionLogContext.Current` (a new `AsyncLocal` mirror of the pushed id) by wrapping the message in an +`ExecutionTaggedLogMessage` (`ToString()` unchanged, so stdout and TestKit filters see the same text). The logger +actor re-pushes that id while it writes the line. + +**Per-execution capture without a schema change (#56).** The decision was to add no replicated column. Instead, +the host pipeline gains `Commons.Observability.ExecutionLogCaptureSink`. While a run is traced, its step logger +registers its `ExecutionId` in `ExecutionLogCapture`: the site `ScriptLogger` registers from the launcher, +plus each inline `CallShared` child's id, and the central `InboundScriptLogger` registers from the executor. The +sink hands each line tagged with a registered id to that logger, which emits it as a `ScriptLog` row with +`LogSource = "node"` and `ScriptTraceExtra.LogCategory` = the logger category. Consequences: + +- **Untraced runs cost ~nothing.** The sink reads one volatile counter and returns. An untraced step logger never + registers. +- **Same bounds as every other line.** Node lines count against `MaxLogLinesPerRun` together with the script's + own lines and are clipped at 2 000 chars. They ride the collector's low-priority lane and pass the same + redactor inline and in the store. +- **No double capture.** The step loggers' own node forwards (`ScriptLogger`, `TraceCapturingLogger`, + `InboundScriptLogger`) run inside `ExecutionLogCapture.Suppress()`, and the sink suppresses itself while it calls + a target. The registration is declared inside the launcher's and executor's `try`, so it ends before any catch + block logs the run's outcome, which is already the `ScriptRun` / inbound row. `FlushDropped` also closes it, so + no node line lands after the closing row. +- **What it sees** is what the node logs: its minimum level and per-source overrides apply first, so a node at + Information never yields Debug lines. A line logged after the run ends (for example a late Akka logger-actor + write) is not captured; it still reaches the node log. +- **Graph and UI.** `FlowGraphBuilder` lists node lines in `FlowGraph.NodeLogs` in time order and never folds + them onto a step, because no step can honestly claim another actor's line. The Flow Debugger page renders them + in a **Node log** card under the detail panel (`FlowNodeLogPanel`, `data-test="flow-nodelog-panel"`), grouped + per execution under that execution's run step (the title selects it), with an `All | Warn +` filter and the + short logger name. Live and Replay build the graph from the same rows, so site scope and the `RequireFlowDebugger` + policy govern them as they govern every other row. CLI `--show-logs` prints them as a trailing `node log (n lines):` block. +- **Mixed versions.** An old central projects `node` rows like any `ScriptLog` row and folds them onto the anchor + step. An old site sends none. + diff --git a/docs/requirements/Component-CentralUI.md b/docs/requirements/Component-CentralUI.md index 9212230e..53a176b6 100644 --- a/docs/requirements/Component-CentralUI.md +++ b/docs/requirements/Component-CentralUI.md @@ -246,7 +246,7 @@ Per-leaf alarm rendering (leaf nodes are individual conditions for native alarms - **`/deployment/flow-debugger`** (nav: Deployment → Flow Debugger; design `docs/plans/2026-09-05-flow-debugger-design.md`, plan `docs/plans/2026-09-05-flow-debugger.md`). Runs one entry point with operator-supplied inputs and renders every step the run passes through as a **four-lane swimlane** (Central / Site / Tags / **External**) — request, route call, site script run, attribute writes, attribute waits, **outbound API / database / notification calls**, response — each node carrying its input, output, duration and outcome; a tabbed detail panel (Input · Output · Writes *or* Lifecycle · Timing, plus a *Where this ran* column) opens on the selected node with `Open in Debug View` (script entries, where the instance is known) and `Audit rows (n)` (→ `/audit/log?executionId=`) drill-ins. - **Two modes.** *Live* is a real run — the method script executes on the active central node with tracing on, or a real attribute write goes through the routed-write path and the site's triggered run is polled back — audited like any other call. *Replay* executes nothing: it rebuilds the flow from an existing execution's `ScriptTrace` audit rows plus its `ApiOutbound` / `DbOutbound` / `Notification` rows (`?executionId=` drill-in from the Audit Log drawer's and the Execution Chain page's **Open in Flow Debugger** actions). - **External lane (v1.1, plan `docs/plans/2026-09-06-flow-debugger-outbound-calls.md`).** Every `ExternalSystem.Call/CachedCall`, `Database.*` and `Notify.Send` a traced run makes is a node on the fourth lane — kinds `ApiCall` / `DbCall` / `Notify` (eyebrows `API CALL` / `DATABASE` / `NOTIFY`), title = the system.method / connection / list, a status pill (`Ok` / `Pending` / `Parked` / `Failed`) plus `sync` | `cached` | `notify`. **One node per operation:** a cached call's or notification's later lifecycle rows (Forwarded → Attempted → Delivered / Parked, written minutes later by the S&F forwarder or the Notification Outbox) fold into the node (`FlowStep.Lifecycle`, a Lifecycle tab in the detail panel with *Delivered by*) instead of drawing four boxes. A sync call sits in the execution chain; a cached call or notification hangs off it on a dashed **async** connector, and a trigger cascade's spawn edge carries a **bolt badge on the connector's riser** — the edge itself keeps an ordinary arrowhead (the bolt was the arrowhead until 2026-09-08, and on the upward Tags→Site hop it read as a broken arrow). The spawn edge starts at the parent's **last write of the attribute the child's `triggerAttribute` names** (`FlowGraphBuilder`); only when the child names no attribute, or the parent never wrote it, does the timestamp rule (last non-async parent step at or before the child) decide — a burst of writes landing in one millisecond used to draw the cascade from the last of them rather than the one that fired it. A Live run returns only the rows the run itself emitted, so a graph left with `Pending` nodes **refreshes itself** through the Replay command every 5 s for up to 2 min (page constants), and a *Refresh outcomes* button re-reads on demand in either mode; the state chip stays *Completed* — pending outbound work is not a failed run. A refresh **merges** the re-read rows into the run's known rows by `EventId` (fresh copy wins) and rebuilds the graph from the union, so it only ever adds nodes: the site's outbound rows reach central's audit store by telemetry seconds after the run returned them inline, and a Replay read taken in between would otherwise erase an already-drawn node (observed on the rig 2026-09-06 with a resolved cached DB write). The union is exact because the inline rows are the very `AuditEvent` objects the site writer persists. **v1.2 (follow-ups plan `docs/plans/2026-09-06-flow-debugger-followups.md`, register row 111 closed):** a folded node carries its `CorrelationId` (`FlowStep.CorrelationId` — the `TrackedOperationId` / `NotificationId`), so the detail panel deep-links to **`/site-calls/report?correlationId=`** / **`/notifications/report?correlationId=`** (*Open in Site Calls* / *Open in Notification report*; both pages accept that query, pre-filter to the one row through an additive per-id query filter — `SiteCallQueryRequest.TrackedOperationIdFilter` / `NotificationOutboxQueryRequest.NotificationIdFilter` — show a removable *Operation* / *Notification* pill and auto-open the row's detail modal; note `NotificationId` is minted as a Guid in **`N` form** — no dashes — so the Notify link passes `N` and the report page normalises any Guid-shaped value to `N`, while `TrackedOperationId` is a `varchar(36)` `D` string and the Site Calls filter binds a `varchar` parameter for the PK seek), and a **`Parked` node offers Retry / Discard in place**: the same site-scope re-check, confirm dialog (Discard = danger) and central→site / Notification Outbox relay the report pages use (`IFlowDebugService.RetryOutboundAsync` / `DiscardOutboundAsync` → `CommunicationService`), then the page re-polls Replay (5 s / 2 min) until the node leaves `Parked`. **Prediction is async-safe:** `FlowDebugService.PredictMethodAsync` resolves route targets by a resolve-and-rewalk loop — its original blocking resolver deadlocked the whole Blazor circuit on the renderer sync context the moment a method routing to a site script was chosen (found 2026-09-06; pinned by a single-thread-pump unit test and the Playwright `FlowDebuggerTests`, which log in through the fixture and run a Live run of an ephemeral method in a real browser). -- **Step logs and exceptions (v1.4, 2026-09-09, design `docs/plans/2026-09-09-flow-debugger-step-logs-design.md`).** A traced run shows, **on the node that produced them**, the exception a failing step threw and every line the script (or the runtime on its behalf) logged. A log line is an ordinary audit row — `ScriptTrace` / `ScriptLog`, one per line — that `FlowGraphBuilder` folds into its owning step's `FlowStep.Logs` and **never draws as a node**; attribution is `Extra.stepEventId` when the emitting helper pre-minted its step id, else the execution's anchor row (`ScriptRun` on a site, `InboundRequest` / the debugger's synthesized `RouteCall` root centrally), else that execution's first step, else `FlowGraph.UnattachedLogLines`. Rendering: a node footer badge (`✕ n` errors, `! n` warnings, `≡ n` info, highest severity first, `data-test="flow-node-logs"`, hidden with no lines); a failed node's subtitle becomes `ExceptionType: message` (namespace stripped, innermost exception, generic-safe) fed by the new `FlowStep.ErrorDetail`; a **Log (n)** tab in the detail panel (`flow-step-tab-log`) carrying the full exception block first, then the lines under an `All | Warn +` filter with a copy button and a *"n more on <step>"* cross-step hint that selects the named step; and a `Log: n errors · n warnings · n info` count in the status strip (`flow-log-counts`) that counts LINES, not steps — a `Log.Error` line is not a failed step and never moves the state chip. Two truncation notes sit beside it: `flow-logs-truncated` (*inline log lines capped — refresh outcomes pulls the rest*, from `FlowDebugRunResult.LogsTruncated`; it clears once a refresh merges in more log rows, because Replay reads the complete set) and `flow-unattached-logs`. Live and Replay read the same rows, so the two modes render identically once telemetry has landed. +- **Step logs and exceptions (v1.4, 2026-09-09, design `docs/plans/2026-09-09-flow-debugger-step-logs-design.md`).** A traced run shows, **on the node that produced them**, the exception a failing step threw and every line the script (or the runtime on its behalf) logged. A log line is an ordinary audit row — `ScriptTrace` / `ScriptLog`, one per line — that `FlowGraphBuilder` folds into its owning step's `FlowStep.Logs` and **never draws as a node**; attribution is `Extra.stepEventId` when the emitting helper pre-minted its step id, else the execution's anchor row (`ScriptRun` on a site, `InboundRequest` / the debugger's synthesized `RouteCall` root centrally), else that execution's first step, else `FlowGraph.UnattachedLogLines`. Rendering: a node footer badge (`✕ n` errors, `! n` warnings, `≡ n` info, highest severity first, `data-test="flow-node-logs"`, hidden with no lines); a failed node's subtitle becomes `ExceptionType: message` (namespace stripped, innermost exception, generic-safe) fed by the new `FlowStep.ErrorDetail`; a **Log (n)** tab in the detail panel (`flow-step-tab-log`) carrying the full exception block first, then the lines under an `All | Warn +` filter with a copy button and a *"n more on <step>"* cross-step hint that selects the named step; and a `Log: n errors · n warnings · n info` count in the status strip (`flow-log-counts`) that counts LINES, not steps — a `Log.Error` line is not a failed step and never moves the state chip. Two truncation notes sit beside it: `flow-logs-truncated` (*inline log lines capped — refresh outcomes pulls the rest*, from `FlowDebugRunResult.LogsTruncated`; it clears once a refresh merges in more log rows, because Replay reads the complete set) and `flow-unattached-logs`. Live and Replay read the same rows, so the two modes render identically once telemetry has landed. **Node log (2026-11-10, Gitea #56):** a traced run's `ScriptLog` rows with source `node` are other actors' node-log lines for that execution, such as the Instance Actor, a DCL actor or a protocol adapter (site) or a callee of the method (central). `FlowGraphBuilder` puts them in `FlowGraph.NodeLogs` rather than on a step. The page shows them in a **Node log** card below the detail panel (`FlowNodeLogPanel`, `flow-nodelog-panel`): one group per execution, titled by its run step (clicking the title selects the step), with `All | Warn +`, time, level, short logger name and message, and the exception inline. The card is hidden when there are none. They come from the same rows as everything else, so site scope and `RequireFlowDebugger` apply unchanged. - **Authorization (arch-review F3).** The page is `RequireFlowDebugger` — `AuthorizationPolicies.FlowDebuggerAccessRoles` = Deployer, Administrator, Viewer — so an auditor can open it and Replay a past execution without the ability to run anything, and `FlowDebugReplayCommand` accepts the same set. **Everything that executes stays Deployer-only:** the three run commands (`FlowDebugRunMethodCommand` / `FlowDebugRunScriptCommand` / `FlowDebugRunValueChangeCommand`), the Live entry-point controls, the parked-node Retry/Discard actions and the `?methodId=` / `?instanceId=` / `?script=` drill-ins; for a non-Deployer the page pins itself to Replay mode. - **Two entry points** (script entry redesigned 2026-09-08, `docs/plans/2026-09-08-flow-debugger-script-entry-design.md`). An inbound API method (**the same `ParameterValueForm` the script pane uses**, generated from the method's `ParameterDefinitions` — typed inputs, nested object groups, add/remove list item editors, `$ref:lib:` resolution, inline validation — plus a **Form | Raw JSON** toggle whose raw mode is a Monaco JSON editor for the whole request body, parsed and validated against the method's schema on every edit; Run is disabled while either surface is invalid, and a failed parse is never sent — Gitea #37, `docs/plans/2026-09-10-flow-debugger-method-params-design.md`; the pre-#37 pane was one text box per top-level field with page-side coercion, which could not take an array-of-object parameter at all) or a **site script** (Site → Instance → Script pickers, site-scope filtered): a script whose trigger is ValueChange or Conditional shows one *New value for ``* field, with the attribute derived from the script's own trigger configuration rather than picked; every other script kind (Call, Interval, Expression, or no trigger) shows a `ParameterValueForm` generated from the script's `ParameterDefinitions`, or a "this script takes no parameters" note when there are none. A method-entry Live run is additionally site-scoped **at route time** on the server (`RouteHelper.WithSiteScope` → `SITE_SCOPE_DENIED`, arch-review F2), so an operator cannot reach a site outside their scope by choosing a method that routes there. Both entry points pick the target instance through the shared **`InstancePicker`** combobox (2026-09-08, `docs/plans/2026-09-08-instance-picker-design.md`): a text field whose dropdown is the site's area tree (`InstanceTreeBuilder` — all areas collapsed on open, un-areaed instances at the root, orphaned rows surface at the root), typed text filters by instance name and expands to the matches, Enter picks the first visible match, Escape restores the selection. - **Predicted graph first.** Choosing an entry point renders the statically predicted shape (`FlowShapePredictor`, Script Analysis REQ-SA-7) before anything runs — nodes whose target depends on inputs render dashed; after a run, predicted nodes the run never produced render greyed. diff --git a/docs/requirements/Component-Host.md b/docs/requirements/Component-Host.md index 9ab1f36f..ba403f40 100644 --- a/docs/requirements/Component-Host.md +++ b/docs/requirements/Component-Host.md @@ -162,6 +162,8 @@ The Host must configure Serilog as the logging provider with: - Configuration-driven sink setup (console and file sinks at minimum). - Automatic enrichment of every log entry with `SiteId`, `NodeHostname`, and `NodeRole` properties sourced from `NodeConfiguration`. - Structured (machine-parseable) output format. +- **Akka logging through the same pipeline (Gitea #120).** `akka.loggers` names `Host.Actors.SerilogAkkaLogger`, so every Akka `ILoggingAdapter` line is written to the static Serilog logger (file sinks, enrichers) rather than Akka's stdout-only default logger. `SourceContext` is the logging class's full name, `AkkaSource` is the actor path, and the event keeps Akka's timestamp. `akka.loglevel` stays `INFO`, so Akka Debug lines are filtered at the adapter as before. An `ExecutionTaggedLogMessage` (from an execution-aware adapter) has its `ExecutionId` re-pushed while the line is written. +- **Per-execution capture sink (Gitea #56).** `ExecutionLogCaptureSink` is attached directly (never behind an async wrapper, because its de-duplication guard is per thread). It copies lines tagged with a traced execution's `ExecutionId` into that run's Flow Debugger step log, and returns after one volatile read when nothing is traced. ### REQ-HOST-8a: Dead Letter Monitoring diff --git a/docs/requirements/Component-InboundAPI.md b/docs/requirements/Component-InboundAPI.md index 80b67485..3b70c691 100644 --- a/docs/requirements/Component-InboundAPI.md +++ b/docs/requirements/Component-InboundAPI.md @@ -316,6 +316,11 @@ backed by `InboundScriptLogger`: - **Bounded:** `ScadaBridge:InboundApi:MaxLogLinesPerRun` (default 200, validated `> 0`) caps the rows one request may emit, messages are clipped at 2 000 characters, and one closing `warn` row names the dropped count. +- **Node lines (Gitea #56):** on a traced request, other central node-log lines tagged with the + request's `ExecutionId` (the executor pushes it for the whole execution) are copied into `ScriptLog` + rows with source `node` and the logger category, under the same cap. `InboundScriptLogger.CaptureNodeLines` + is opened inside the executor's `try`, so the executor's own outcome lines in its catch blocks are + not copied. The script's own `Log.*` forward is suppressed, so it is not copied twice either. #### Script exception detail diff --git a/docs/requirements/Component-SiteRuntime.md b/docs/requirements/Component-SiteRuntime.md index f533189b..331759b0 100644 --- a/docs/requirements/Component-SiteRuntime.md +++ b/docs/requirements/Component-SiteRuntime.md @@ -584,7 +584,7 @@ Available to all script runs and alarm on-trigger runs: - **Runtime lines land on the step that produced them.** While a run is traced, `ScriptRuntimeContext` wraps its own `ILogger` in a `TraceCapturingLogger`, which forwards everything to the inner logger unchanged and additionally copies **Information and above** into `ScriptLog` rows with `logSource = "runtime"` (Debug/Trace are deliberately not captured — internal chatter). `IsEnabled` returns true for Information and above regardless of the node's minimum level, because those entries are trace data rather than node log output. Attribution rides an ambient `TraceStepScope` (`AsyncLocal`): `SetAttribute`, `WriteBatchAndWait`, `WaitInternal` and the synchronous `ExternalSystem.Call` pre-mint their step row's `EventId`, open the scope around their body and pass the id to `EmitTrace`, so a warning the runtime logs inside a write shows on that write's node. Everything else falls back to the run's anchor `ScriptRun` row. **Build `ScriptLogger` over the UNDECORATED logger** — `TraceCapturingLogger`'s constructor rejects an inner `TraceCapturingLogger`, since double wrapping would emit two rows per line. - **Bounded (D7).** `ScadaBridge:SiteRuntime:MaxLogLinesPerRun` (default 200, validated `> 0`) caps the rows one run may emit; messages are clipped at 2 000 characters. Lines past the cap are counted and dropped, and a single closing `warn` / `runtime` row naming the dropped count is flushed at run end (it bypasses the counter — it is the one row that must always land). - **Exception detail.** A failed run's `ScriptRun` row now carries `errorDetail = ex.ToString()` alongside the existing one-line `errorMessage`, so the Flow Debugger can show type, message, stack and inner exception. A timeout emits no detail — an `OperationCanceledException` stack is noise. -- **`ExecutionId` on node-log lines across actor hops (Gitea #56).** The launcher pushes the run's `ExecutionId` / `InstanceName` / `ScriptName` onto the Serilog `LogContext` for the run, and the host enables `Enrich.FromLogContext()`. `LogContext` does not cross an Akka message hop, so every request a run sends carries its id (`SourceExecutionId` / `ParentExecutionId`, exposed as `Commons.Observability.IExecutionCorrelated`) and the Instance, Script, Alarm, Deployment Manager and DCL actors re-push it for that one message in `AroundReceive` — a node-log line the Instance Actor, or a protocol adapter on the write path, writes while serving the run carries the run's id; a message naming no execution costs one type test and carries nothing (the sender's ambient context never leaks in). An `AttributeValueChanged` whose writer was *inferred* by the trace arm is not stamped. Only the id rides — never a value. The DCL actors' own Akka `_log` lines bypass Serilog and are untagged (Gitea #120). This is node-log enrichment only; the Flow Debugger does not yet show these lines (#56 remains open for the per-execution sink). +- **`ExecutionId` on node-log lines across actor hops (Gitea #56).** The launcher pushes the run's `ExecutionId` / `InstanceName` / `ScriptName` onto the Serilog `LogContext` for the run, and the host enables `Enrich.FromLogContext()`. `LogContext` does not cross an Akka message hop, so every request a run sends carries its id (`SourceExecutionId` / `ParentExecutionId`, exposed as `Commons.Observability.IExecutionCorrelated`) and the Instance, Script, Alarm, Deployment Manager and DCL actors re-push it for that one message in `AroundReceive` — a node-log line the Instance Actor, or a protocol adapter on the write path, writes while serving the run carries the run's id; a message naming no execution costs one type test and carries nothing (the sender's ambient context never leaks in). An `AttributeValueChanged` whose writer was *inferred* by the trace arm is not stamped. Only the id rides — never a value. The DCL actors' own Akka `_log` lines are tagged too: they log through `ExecutionAwareLogging.GetLogger(Context)`, and the host's `SerilogAkkaLogger` (`akka.loggers`) re-pushes the id when it writes them to Serilog (Gitea #120). **While a run is traced, these lines are also copied into it** (Gitea #56): the launcher registers the run's id with `ExecutionLogCapture` (plus each inline `CallShared` child's id), and the host's `ExecutionLogCaptureSink` hands each tagged line to the run's `ScriptLogger`, which writes a `ScriptLog` row with source `node` and the logger category. These rows share the per-run line cap, the 2 000-char clip, the low-priority inline lane and the redactor. Untraced runs never register, and the sink returns after one volatile read. The logger's own forwards are suppressed, so no line is copied twice, and the registration ends before the launcher's catch blocks log the outcome. Design: step-logs design §12. - **`Console.WriteLine` is not the logging surface on a site.** `System` is imported, so it compiles, and the Central UI Test Run sandbox does capture it; but on a site node `Console.Out` is process-global and shared by every concurrent script run, so per-run capture is unsound. `Log.*` is the leveled, per-run replacement, and the sandbox's mirror writes to the same console pane. ### Parameter Access diff --git a/src/ZB.MOM.WW.ScadaBridge.CLI/Commands/FlowDebugTableProjection.cs b/src/ZB.MOM.WW.ScadaBridge.CLI/Commands/FlowDebugTableProjection.cs index f278a1dd..ac290edb 100644 --- a/src/ZB.MOM.WW.ScadaBridge.CLI/Commands/FlowDebugTableProjection.cs +++ b/src/ZB.MOM.WW.ScadaBridge.CLI/Commands/FlowDebugTableProjection.cs @@ -187,9 +187,27 @@ internal static class FlowDebugTableProjection } } + // ScadaBridge#56: other actors' lines for the traced executions are not on any step; with + // --show-logs they print as one trailing block, each line naming its logger. + if (showLogs && graph.NodeLogs is { Count: > 0 } nodeLogs) + { + rows.Add(new JsonObject { ["note"] = JsonValue.Create($"node log ({nodeLogs.Count} line{(nodeLogs.Count == 1 ? "" : "s")}):") }); + foreach (var line in nodeLogs) + rows.Add(new JsonObject { ["note"] = JsonValue.Create(FormatNodeLogLine(line)) }); + } + return rows; } + /// Formats one node-log line as HH:mm:ss.fff LEVEL [Category] message, the category without its namespace. + private static string FormatNodeLogLine(FlowLogLine line) + { + var time = line.OccurredAtUtc.ToUniversalTime().ToString("HH:mm:ss.fff", CultureInfo.InvariantCulture); + var level = (line.Level ?? "info").ToUpperInvariant().PadRight(5); + var category = line.Category is { Length: > 0 } c ? c[(c.LastIndexOf('.') + 1)..] : "node"; + return $" {time} {level} [{category}] {line.Message}"; + } + /// Formats one as HH:mm:ss.fff LEVEL source message (UTC, level upper-cased and padded to 5 chars). private static string FormatLogLine(FlowLogLine line) { diff --git a/src/ZB.MOM.WW.ScadaBridge.CLI/README.md b/src/ZB.MOM.WW.ScadaBridge.CLI/README.md index db501b6d..adee03bb 100644 --- a/src/ZB.MOM.WW.ScadaBridge.CLI/README.md +++ b/src/ZB.MOM.WW.ScadaBridge.CLI/README.md @@ -2727,7 +2727,10 @@ Pass `--show-logs` (on `run-method`, `run-script`, `run-value-change` and `repla each step's log lines immediately under its row, as additional indented `note` rows — ` HH:mm:ss.fff LEVEL source message` (UTC, level upper-cased) — and, for a failed step whose error carries an exception detail, the first three lines of it (` exception: `, -then two more lines indented four spaces). Off by default; the `logs` count column is always +then two more lines indented four spaces). Node-log lines (other actors' lines for the traced +executions, Gitea #56) are on no step, so the `logs` column does not count them. With +`--show-logs` they print as one trailing block, `node log (n lines):` followed by +` HH:mm:ss.fff LEVEL [Logger] message` rows. Off by default; the `logs` count column is always shown regardless of this flag. #### `flow-debug run-method` @@ -2744,7 +2747,7 @@ scadabridge --url flow-debug run-method --method-id [--params | `--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. **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. | -| `--show-logs` | no | Print each step's `ScriptLog` lines and exception detail as indented lines under its row (table output only; default off) | +| `--show-logs` | no | Print each step's `ScriptLog` lines and exception detail as indented lines under its row, plus a trailing node-log block (table output only; default off) | Parameters that fail schema validation are reported as `VALIDATION_FAILED` without running the script. @@ -2770,7 +2773,7 @@ scadabridge --url flow-debug run-script --instance-id --script flow-debug run-value-change --instance-id --attrib | `--attribute` | yes | Canonical attribute name to write | | `--value` | yes | Value to write, in canonical string form | | `--wait-seconds` | no | How long to wait for a triggered run before reporting `NO_TRIGGER_WITHIN_WINDOW` (default 45) | -| `--show-logs` | no | Print each step's `ScriptLog` lines and exception detail as indented lines under its row (table output only; default off) | +| `--show-logs` | no | Print each step's `ScriptLog` lines and exception detail as indented lines under its row, plus a trailing node-log block (table output only; default off) | The client waits `--wait-seconds` + 25 (no separate option — the client's HTTP wait always derives from `--wait-seconds`). The write itself is real — the attribute changes — and is the root step of the flow. @@ -2812,7 +2815,7 @@ scadabridge --url flow-debug replay --execution-id [--show-logs] | Option | Required | Description | |--------|----------|-------------| | `--execution-id` | yes | Any execution ID in the chain — the root is resolved server-side | -| `--show-logs` | no | Print each step's `ScriptLog` lines and exception detail as indented lines under its row (table output only; default off) | +| `--show-logs` | no | Print each step's `ScriptLog` lines and exception detail as indented lines under its row, plus a trailing node-log block (table output only; default off) | Only flows whose site legs were traced (a Live run, or a method with `--trace-all-calls` set) have site steps to replay; an untraced call shows its central `RouteCall` step plus the diff --git a/src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Deployment/FlowNodeLogPanel.razor b/src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Deployment/FlowNodeLogPanel.razor new file mode 100644 index 00000000..a40dac41 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Deployment/FlowNodeLogPanel.razor @@ -0,0 +1,151 @@ +@using System.Globalization +@using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging +@* + Flow Debugger — node log (ScadaBridge#56). The lines OTHER actors wrote while serving a traced + execution (the Instance Actor, the DCL and its protocol adapters, central callees of a method), + copied by the node's per-execution sink into ScriptLog rows with source "node". They come from other + threads and actors, so no step can honestly claim them: they are listed per execution instead of + folded onto a node. Live and Replay read the same rows, so the panel is identical in both modes, and + what it shows is already scoped by whatever scoped the run's rows (site scope, role policy). +*@ + +@if (Lines.Count > 0) +{ +
+
+
+
Node log
+ @CountText +
+ + +
+
+
+ Lines other actors logged for these executions (Instance Actor, data connections, adapters) — + what the node's log level kept, under the run's log-line cap. +
+ @foreach (var group in Groups) + { +
+
+ @if (group.Anchor is { } anchor && OnSelectStep.HasDelegate) + { + + } + else if (group.Anchor is { } named) + { + @named.Title + } + else + { + execution + } + @(group.ExecutionId?.ToString() ?? "—") +
+ @if (group.Visible.Count == 0) + { +
No warnings or errors.
+ } + else + { + + + + @foreach (var line in group.Visible) + { + + + + + + + } + +
Time (UTC)LevelLoggerMessage
@line.OccurredAtUtc.ToUniversalTime().ToString("HH:mm:ss.fff", CultureInfo.InvariantCulture)@line.Level@ShortCategory(line.Category) + @line.Message + @if (!string.IsNullOrEmpty(line.ExceptionMessage)) + { +
+ @line.ExceptionMessage + @if (!string.IsNullOrEmpty(line.ExceptionDetail)) + { +
+ detail + 
@line.ExceptionDetail
+
+ } +
+ } +
+ } +
+ } +
+
+} + +@code { + /// The graph whose are listed; nothing renders without node lines. + [Parameter] public FlowGraph? Graph { get; set; } + + /// Selects an execution's anchor step when its title is clicked. + [Parameter] public EventCallback OnSelectStep { get; set; } + + private bool _warnOnly; + + private IReadOnlyList Lines => Graph?.NodeLogs ?? []; + + private sealed record Group(Guid? ExecutionId, FlowStep? Anchor, IReadOnlyList Visible); + + /// + /// One group per execution, in the order its first line appeared; the anchor is that execution's + /// script run / inbound request / route call step, so the title names the run the lines belong to. + /// + private IEnumerable Groups + => Lines.GroupBy(l => l.ExecutionId).Select(g => new Group( + g.Key, + Anchor(g.Key), + g.Where(l => !_warnOnly || !IsLow(l.Level)).ToList())); + + private string CountText + { + get + { + var errors = Lines.Count(l => string.Equals(l.Level, "error", StringComparison.OrdinalIgnoreCase)); + var warnings = Lines.Count(l => string.Equals(l.Level, "warn", StringComparison.OrdinalIgnoreCase)); + var other = Lines.Count - errors - warnings; + return $"{Lines.Count} line{(Lines.Count == 1 ? "" : "s")} · {errors} error{(errors == 1 ? "" : "s")} · " + + $"{warnings} warning{(warnings == 1 ? "" : "s")} · {other} info/debug"; + } + } + + private FlowStep? Anchor(Guid? executionId) + => executionId is null || Graph is null + ? null + : Graph.Steps + .Where(s => s.ExecutionId == executionId) + .OrderBy(s => s.Kind switch + { + FlowStepKind.ScriptRun => 0, + FlowStepKind.InboundRequest => 1, + FlowStepKind.RouteCall => 2, + _ => 3, + }) + .FirstOrDefault(); + + private static bool IsLow(string level) + => string.Equals(level, "debug", StringComparison.OrdinalIgnoreCase) + || string.Equals(level, "info", StringComparison.OrdinalIgnoreCase); + + /// The logger category without its namespace (the full name is the cell's tooltip). + private static string ShortCategory(string? category) + { + if (string.IsNullOrEmpty(category)) return "—"; + var dot = category.LastIndexOf('.'); + return dot >= 0 && dot < category.Length - 1 ? category[(dot + 1)..] : category; + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Pages/Deployment/FlowDebugger.razor b/src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Pages/Deployment/FlowDebugger.razor index d7717f18..fa5cedc2 100644 --- a/src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Pages/Deployment/FlowDebugger.razor +++ b/src/ZB.MOM.WW.ScadaBridge.CentralUI/Components/Pages/Deployment/FlowDebugger.razor @@ -352,5 +352,10 @@ OnRetry="RetryCallback" OnDiscard="DiscardCallback" ActionInProgress="_actionInProgress" OnSelectStep="OnSelectStep" /> + + @* ── Node log (ScadaBridge#56): other actors' lines for the traced executions ── *@ +
+ +
diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogCapture.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogCapture.cs new file mode 100644 index 00000000..567de91c --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogCapture.cs @@ -0,0 +1,216 @@ +using System.Collections.Concurrent; +using Serilog.Core; +using Serilog.Events; + +namespace ZB.MOM.WW.ScadaBridge.Commons.Observability; + +/// One node-log line copied for a traced execution (ScadaBridge#56). +/// When the line was logged. +/// debug | info | warn | error. +/// The logger category (SourceContext), when the line had one. +/// The rendered message. +/// The exception attached to the line, if any. +public sealed record CapturedLogLine( + DateTime OccurredAtUtc, string Level, string? Category, string Message, Exception? Exception); + +/// Receives the node-log lines of one traced execution (ScadaBridge#56). +public interface IExecutionLogTarget +{ + /// Records one line. Called on the logging thread; must not throw and must not block. + /// The captured line. + void Capture(CapturedLogLine line); +} + +/// +/// The process-wide set of executions whose node-log lines are being copied into their Flow +/// Debugger trace (ScadaBridge#56). +/// +/// +/// What it is for. Every node-log line written while a correlated message is served +/// carries the run's ExecutionId (). While a run is traced, +/// its step logger registers here under that id, and hands it +/// each such line, wherever it was logged: the Instance Actor, a DCL actor (through the Akka bridge, +/// #120), a protocol adapter, an HTTP client. The step logger turns each line into a +/// ScriptLog row with source node, under the run's existing caps and redaction. +/// Cost when nothing is traced. The sink reads one volatile counter and returns. No +/// property lookup, no rendering, no allocation. +/// No double capture. The step loggers already turn their own lines into rows (the +/// script's Log.* calls and the runtime lines a traced context captures). They write those +/// lines to the node logger inside , so the sink skips them. The sink also +/// suppresses itself while it calls a target, so a line the target logs while emitting its row +/// cannot loop back. +/// Lifetime. A registration is disposed when the run's step log closes (the site +/// launcher's and inbound executor's run end). A line logged after that is not captured: it still +/// reaches the node log, just not the trace. +/// +public static class ExecutionLogCapture +{ + private static readonly ConcurrentDictionary Targets = new(); + private static int _count; + + [ThreadStatic] + private static int _suppressDepth; + + /// True when at least one execution is registered. One volatile read. + public static bool HasTargets => Volatile.Read(ref _count) > 0; + + /// True while the current thread is inside . + public static bool IsSuppressed => _suppressDepth > 0; + + /// Registers for the lines tagged with . + /// The traced execution. + /// Where its lines go. + /// + /// A disposable that removes the registration (idempotent). When the id is already registered + /// the first registration is kept and the returned disposable does nothing. + /// + public static IDisposable Register(Guid executionId, IExecutionLogTarget target) + { + ArgumentNullException.ThrowIfNull(target); + if (!Targets.TryAdd(executionId, target)) + { + return NoOp.Instance; + } + + Interlocked.Increment(ref _count); + return new Registration(executionId, target); + } + + /// Finds the target registered for an execution. + /// The execution id. + /// The registered target, when found. + /// when the execution is registered. + public static bool TryGetTarget(Guid executionId, out IExecutionLogTarget target) + => Targets.TryGetValue(executionId, out target!); + + /// + /// Stops the sink from capturing lines logged on this thread until the scope is disposed. Used + /// around writes whose line is already a trace row, so it is not copied a second time. + /// + /// A disposable that ends the suppression; dispose it on the same thread. + public static SuppressScope Suppress() + { + _suppressDepth++; + return new SuppressScope(true); + } + + /// Ends one on the thread that started it. + public readonly struct SuppressScope : IDisposable + { + private readonly bool _active; + + internal SuppressScope(bool active) => _active = active; + + /// Ends the suppression. + public void Dispose() + { + if (_active && _suppressDepth > 0) + { + _suppressDepth--; + } + } + } + + /// Maps a Serilog level to the step-log level names. + /// The Serilog level. + /// debug, info, warn or error. + public static string LevelName(LogEventLevel level) => level switch + { + LogEventLevel.Verbose or LogEventLevel.Debug => "debug", + LogEventLevel.Information => "info", + LogEventLevel.Warning => "warn", + _ => "error", + }; + + private sealed class Registration(Guid executionId, IExecutionLogTarget target) : IDisposable + { + private int _disposed; + + public void Dispose() + { + if (Interlocked.Exchange(ref _disposed, 1) != 0) + { + return; + } + + if (Targets.TryRemove(new KeyValuePair(executionId, target))) + { + Interlocked.Decrement(ref _count); + } + } + } + + private sealed class NoOp : IDisposable + { + public static readonly NoOp Instance = new(); + + public void Dispose() + { + } + } +} + +/// +/// The Serilog sink behind (ScadaBridge#56): copies each line +/// tagged with a registered execution's ExecutionId to that execution's target. +/// +/// +/// It sees what the node logs: the configured minimum level and every per-source override +/// apply before it, so a node at Information never hands it a Debug line. It must be attached +/// directly, never behind an async wrapper, because is +/// per thread. +/// +public sealed class ExecutionLogCaptureSink : ILogEventSink +{ + /// Copies one line to its execution's target, when that execution is being traced. + /// The Serilog event. + public void Emit(LogEvent logEvent) + { + if (!ExecutionLogCapture.HasTargets || ExecutionLogCapture.IsSuppressed || logEvent is null) + { + return; + } + + if (!logEvent.Properties.TryGetValue(ExecutionLogContext.ExecutionIdProperty, out var value) + || !TryReadGuid(value, out var executionId) + || !ExecutionLogCapture.TryGetTarget(executionId, out var target)) + { + return; + } + + using (ExecutionLogCapture.Suppress()) + { + try + { + var category = logEvent.Properties.TryGetValue(Serilog.Core.Constants.SourceContextPropertyName, out var sc) + && sc is ScalarValue { Value: string s } ? s : null; + target.Capture(new CapturedLogLine( + logEvent.Timestamp.UtcDateTime, + ExecutionLogCapture.LevelName(logEvent.Level), + category, + logEvent.RenderMessage(), + logEvent.Exception)); + } + catch + { + // Deliberate swallow: a debug observer must never fail the write that logged the line. + } + } + } + + private static bool TryReadGuid(LogEventPropertyValue value, out Guid id) + { + switch (value) + { + case ScalarValue { Value: Guid g }: + id = g; + return true; + case ScalarValue { Value: string s } when Guid.TryParse(s, out var parsed): + id = parsed; + return true; + default: + id = Guid.Empty; + return false; + } + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs index 7ccbf1e6..6999cb3a 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionLogContext.cs @@ -32,15 +32,55 @@ public static class ExecutionLogContext /// The log-event property carrying the execution id. public const string ExecutionIdProperty = "ExecutionId"; + /// + /// The innermost execution id pushed on this async flow, or null. Mirrors the + /// on the Serilog LogContext, which cannot be read back. + /// + /// + /// ScadaBridge#120: Akka's ILoggingAdapter hands each line to a logger actor on another + /// thread, where this flow's LogContext is gone. An adapter that captures this value when + /// the line is logged lets the logger actor re-push it when it writes the line to Serilog. + /// + public static Guid? Current => CurrentId.Value; + + private static readonly AsyncLocal CurrentId = new(); + /// Pushes as . /// The execution id; null pushes nothing. /// A disposable that pops the property, or null when nothing was pushed. public static IDisposable? Push(Guid? executionId) - => executionId is { } id ? LogContext.PushProperty(ExecutionIdProperty, id) : null; + { + if (executionId is not { } id) + { + return null; + } + + var previous = CurrentId.Value; + var property = LogContext.PushProperty(ExecutionIdProperty, id); + CurrentId.Value = id; + return new Scope(property, previous); + } /// Pushes the execution a message serves, when it names one. /// Any actor message. /// A disposable that pops the property, or null when the message names no execution. public static IDisposable? PushFor(object? message) => message is IExecutionCorrelated correlated ? Push(correlated.CorrelatedExecutionId) : null; + + /// Pops the pushed property and restores the previous . + private sealed class Scope(IDisposable property, Guid? previous) : IDisposable + { + private int _disposed; + + public void Dispose() + { + if (Interlocked.Exchange(ref _disposed, 1) != 0) + { + return; + } + + CurrentId.Value = previous; + property.Dispose(); + } + } } diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionTaggedLogMessage.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionTaggedLogMessage.cs new file mode 100644 index 00000000..63197823 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Observability/ExecutionTaggedLogMessage.cs @@ -0,0 +1,27 @@ +namespace ZB.MOM.WW.ScadaBridge.Commons.Observability; + +/// +/// An Akka log message together with the execution id that was current when it was logged +/// (ScadaBridge#120). +/// +/// +/// Akka's logging adapter publishes each line to a logger actor, which writes it on its own +/// thread. By then the logging actor's LogContext, including the ExecutionId that +/// pushed for the message being served, is no longer +/// available. An execution-aware adapter wraps the message in this type when +/// is set. The host's Serilog logger actor unwraps it and +/// pushes the id again while it writes the line. +/// returns the inner message's text. A logger that does not know this +/// type, such as Akka's stdout logger during startup or the TestKit's event filters, still sees the +/// same text it would have seen without the wrapper. +/// This type has no Akka dependency. It travels only inside one process, on the local event +/// stream, and is never serialized. +/// +/// The original log message (an Akka LogMessage, or any object). +/// The execution the line was logged for. +public sealed record ExecutionTaggedLogMessage(object? Message, Guid ExecutionId) +{ + /// The inner message's text, unchanged by the wrapper. + /// The formatted inner message, or an empty string when it is null. + public override string ToString() => Message?.ToString() ?? string.Empty; +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraph.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraph.cs index 77ff880b..483645b0 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraph.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraph.cs @@ -16,13 +16,19 @@ public sealed record FlowEdge(Guid FromEventId, Guid ToEventId, bool CrossesBoun /// True when the inline event list was capped (the audit rows remain complete — Replay shows everything). /// True when the inline trace collector dropped low-priority log rows to keep room for the step rows — the audit rows remain complete, so Replay shows every line (design 2026-09-09 D7). /// Count of log lines the builder could not place on any step (design 2026-09-09 D2). +/// +/// Node-log lines copied for the traced executions (source node, ScadaBridge#56), in time +/// order. They are listed per execution, never folded onto a step: they come from other actors and +/// threads, so no step can honestly claim them. Null or empty when there are none. +/// public sealed record FlowGraph( IReadOnlyList Steps, IReadOnlyList Edges, bool Predicted, bool Truncated, bool LogsTruncated = false, - int UnattachedLogLines = 0) + int UnattachedLogLines = 0, + IReadOnlyList? NodeLogs = null) { /// An empty, non-predicted graph. public static FlowGraph Empty { get; } = new(Array.Empty(), Array.Empty(), false, false); diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraphBuilder.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraphBuilder.cs index a839bacb..781375f4 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraphBuilder.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowGraphBuilder.cs @@ -51,6 +51,9 @@ namespace ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; /// dropped and counted in . Within a step, lines are ordered /// by OccurredAtUtc then Seq, with a null Seq sorting last, so same-millisecond /// lines keep their emission order. +/// Node-log lines are listed, not folded (ScadaBridge#56). A ScriptLog row with source +/// node — another actor's line the per-execution sink copied — goes to +/// in time order and never onto a step or into the unattached count. /// /// public static class FlowGraphBuilder @@ -82,9 +85,13 @@ public static class FlowGraphBuilder events = stepEvents.Select(e => e.Event).ToList(); + // ScadaBridge#56: node-log lines (other actors' lines copied for a traced execution) are + // listed per execution, not folded onto a step, so they never count as unattached either. + var nodeLogs = TakeNodeLines(lines); + if (events.Count == 0) return new FlowGraph(Array.Empty(), Array.Empty(), Predicted: false, Truncated: truncated, - LogsTruncated: logsTruncated, UnattachedLogLines: lines.Count); + LogsTruncated: logsTruncated, UnattachedLogLines: lines.Count, NodeLogs: nodeLogs); // Arch-review F5: a step's position in the input is the only cross-node ordering we can trust — // central rows carry central's clock, site rows the site's, and a 1-2 s skew used to sort a whole @@ -268,7 +275,19 @@ public static class FlowGraphBuilder AttachLogLines(steps, lines, out var unattached); return new FlowGraph(steps, edges, Predicted: false, Truncated: truncated, - LogsTruncated: logsTruncated, UnattachedLogLines: unattached); + LogsTruncated: logsTruncated, UnattachedLogLines: unattached, NodeLogs: nodeLogs); + } + + /// + /// Removes the node-log lines (source node, ScadaBridge#56) from + /// and returns them ordered by time, then per-run Seq (null last). Null when there are none. + /// + private static IReadOnlyList? TakeNodeLines(List lines) + { + var node = lines.Where(l => l.IsNodeLine).ToList(); + if (node.Count == 0) return null; + lines.RemoveAll(l => l.IsNodeLine); + return node.OrderBy(l => l.OccurredAtUtc).ThenBy(l => l.Seq ?? int.MaxValue).ToList(); } /// diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStep.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStep.cs index 0af7dfa4..287e37ff 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStep.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStep.cs @@ -84,12 +84,13 @@ public sealed record FlowLifecycleRow( /// Execution the line was written in. /// When the line was written. /// debug | info | warn | error. -/// script (a Log.* call) | runtime (the context's own logger while traced). +/// script (a Log.* call) | runtime (the context's own logger while traced) | node (another node-log line tagged with the execution, ScadaBridge#56). /// The logged message. /// Message of an attached exception, when the line carried one. /// Full ToString() of that exception. /// Step the line belongs to; null = the execution's anchor step (design D2). /// Per-run emission counter, breaking same-millisecond ties in display order. +/// On a node line (ScadaBridge#56): the logger category that wrote it. public sealed record FlowLogLine( Guid EventId, Guid? ExecutionId, @@ -100,7 +101,15 @@ public sealed record FlowLogLine( string? ExceptionMessage, string? ExceptionDetail, Guid? StepEventId, - int? Seq); + int? Seq, + string? Category = null) +{ + /// The of a node-log line copied by the per-execution sink (ScadaBridge#56). + public const string NodeSource = "node"; + + /// True for a node-log line, which the graph lists per execution rather than on a step. + public bool IsNodeLine => string.Equals(Source, NodeSource, StringComparison.Ordinal); +} /// /// One node of the flow graph — a central-side projection of a ScriptTrace / diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStepProjector.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStepProjector.cs index cfb44e7f..33dcc199 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStepProjector.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/FlowStepProjector.cs @@ -102,7 +102,8 @@ public static class FlowStepProjector ExceptionMessage: d.ErrorMessage, ExceptionDetail: d.ErrorDetail, StepEventId: x?.StepEventId, - Seq: x?.Seq); + Seq: x?.Seq, + Category: x?.LogCategory); } /// Projects one outbound audit row onto its lifecycle entry (). diff --git a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/ScriptTraceExtra.cs b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/ScriptTraceExtra.cs index 241a168d..db162fca 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/ScriptTraceExtra.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Commons/Types/Debugging/ScriptTraceExtra.cs @@ -52,9 +52,12 @@ public sealed record ScriptTraceExtra /// On a ScriptLog row: debug | info | warn | error. public string? LogLevel { get; init; } - /// On a ScriptLog row: script (a Log.* call) | runtime (the context's own logger while traced). + /// On a ScriptLog row: script (a Log.* call) | runtime (the context's own logger while traced) | node (any other node-log line tagged with the execution's id, ScadaBridge#56). public string? LogSource { get; init; } + /// On a node ScriptLog row: the logger category (SourceContext) that wrote the line (ScadaBridge#56). + public string? LogCategory { get; init; } + /// On a ScriptLog row: the pre-minted EventId of the step the line belongs to; null = the execution's anchor step (design D2). public Guid? StepEventId { get; init; } diff --git a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs index eee411a7..b3ffdee3 100644 --- a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionActor.cs @@ -1,3 +1,4 @@ +using ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Logging; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using Akka.Actor; using Akka.Event; @@ -32,7 +33,8 @@ public class DataConnectionActor : UntypedActor, IWithTimers { public enum ActiveEndpoint { Primary, Backup } - private readonly ILoggingAdapter _log = Context.GetLogger(); + // ScadaBridge#120: execution-aware, so a line logged while serving a correlated message keeps its ExecutionId. + private readonly ILoggingAdapter _log = ExecutionAwareLogging.GetLogger(Context); private readonly string _connectionName; private IDataConnection _adapter; private readonly DataConnectionOptions _options; @@ -337,7 +339,8 @@ public class DataConnectionActor : UntypedActor, IWithTimers /// /// Enrichment reaches lines written through a Serilog-backed ILogger - here, the protocol /// adapter's own logging on the write path, whose WriteAsync starts inside this scope. This - /// actor's own Akka _log lines go through Akka's logger, not Serilog, and are not enriched. + /// actor's own Akka _log lines are tagged too (Gitea #120): the execution-aware adapter + /// records the id when the line is logged, and the host's Serilog logger actor re-pushes it. /// /// The behaviour that handles the message. /// The message. diff --git a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs index f8b34de9..82a1e84f 100644 --- a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Actors/DataConnectionManagerActor.cs @@ -1,3 +1,4 @@ +using ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Logging; using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; using Akka.Actor; using Akka.Event; @@ -21,7 +22,8 @@ namespace ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors; /// public class DataConnectionManagerActor : ReceiveActor { - private readonly ILoggingAdapter _log = Context.GetLogger(); + // ScadaBridge#120: execution-aware, so a line logged while serving a correlated message keeps its ExecutionId. + private readonly ILoggingAdapter _log = ExecutionAwareLogging.GetLogger(Context); private readonly IDataConnectionFactory _factory; private readonly DataConnectionOptions _options; private readonly ISiteHealthCollector _healthCollector; @@ -242,7 +244,8 @@ public class DataConnectionManagerActor : ReceiveActor /// /// Enrichment reaches lines written through a Serilog-backed ILogger - here, the protocol /// adapter's own logging on the write path, whose WriteAsync starts inside this scope. This - /// actor's own Akka _log lines go through Akka's logger, not Serilog, and are not enriched. + /// actor's own Akka _log lines are tagged too (Gitea #120): the execution-aware adapter + /// records the id when the line is logged, and the host's Serilog logger actor re-pushes it. /// /// The behaviour that handles the message. /// The message. diff --git a/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Logging/ExecutionAwareLogging.cs b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Logging/ExecutionAwareLogging.cs new file mode 100644 index 00000000..7499d089 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.DataConnectionLayer/Logging/ExecutionAwareLogging.cs @@ -0,0 +1,95 @@ +using Akka.Actor; +using Akka.Event; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + +namespace ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Logging; + +/// +/// Creates Akka logging adapters whose lines keep the ExecutionId of the message being +/// served (ScadaBridge#120). +/// +/// +/// An actor that re-pushes an execution id per message in AroundReceive +/// () tags every Serilog-backed ILogger line it +/// writes. An Akka ILoggingAdapter line is different: Akka's logger actor writes it later, on +/// another thread, where the push is no longer in effect. The adapter created here records +/// when the line is logged, by wrapping the message in an +/// . The host's Serilog logger actor pushes the id again while +/// it writes the line. +/// Use it in place of Context.GetLogger(): +/// private readonly ILoggingAdapter _log = ExecutionAwareLogging.GetLogger(Context); +/// Level filtering is unchanged (akka.loglevel). A disabled level allocates nothing, and a +/// line logged while no execution is current is published exactly as Context.GetLogger() +/// would publish it. +/// +public static class ExecutionAwareLogging +{ + /// Creates an execution-aware adapter for the given actor context. + /// The actor context (Context inside an actor). + /// An adapter with the same log source, class and formatter as Context.GetLogger(). + public static ILoggingAdapter GetLogger(IActorContext context) + { + ArgumentNullException.ThrowIfNull(context); + var source = LogSource.Create(context, context.System); + return new ExecutionAwareBusLogging( + context.System.EventStream, source.Source, source.Type, context.System.Settings.LogFormatter); + } + + /// + /// The same publishing behaviour as Akka's (sealed) , except that each + /// message is wrapped in an while an execution id is + /// current. + /// + internal sealed class ExecutionAwareBusLogging : LoggingAdapterBase + { + private readonly LoggingBus _bus; + private readonly string _logSource; + private readonly Type _logClass; + + /// Creates the adapter over the given logging bus. + /// The system's event stream. + /// The log source string (the actor path). + /// The logging class (the actor type). + /// The system's log message formatter. + public ExecutionAwareBusLogging(LoggingBus bus, string logSource, Type logClass, ILogMessageFormatter formatter) + : base(formatter) + { + _bus = bus; + _logSource = logSource; + _logClass = logClass; + } + + /// + public override bool IsDebugEnabled => _bus.LogLevel <= LogLevel.DebugLevel; + + /// + public override bool IsInfoEnabled => _bus.LogLevel <= LogLevel.InfoLevel; + + /// + public override bool IsWarningEnabled => _bus.LogLevel <= LogLevel.WarningLevel; + + /// + public override bool IsErrorEnabled => _bus.LogLevel <= LogLevel.ErrorLevel; + + /// Publishes the line, tagged with the current execution id when there is one. + /// The line's level. + /// The log message. + /// The attached exception, if any. + protected override void NotifyLog(LogLevel logLevel, object message, Exception? cause = null) + { + if (ExecutionLogContext.Current is { } id) + { + message = new ExecutionTaggedLogMessage(message, id); + } + + LogEvent logEvent = logLevel switch + { + LogLevel.DebugLevel => new Debug(cause, _logSource, _logClass, message), + LogLevel.InfoLevel => new Info(cause, _logSource, _logClass, message), + LogLevel.WarningLevel => new Warning(cause, _logSource, _logClass, message), + _ => new Error(cause, _logSource, _logClass, message), + }; + _bus.Publish(logEvent); + } + } +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs index 7600de81..525debfd 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/AkkaHostedService.cs @@ -244,6 +244,12 @@ public class AkkaHostedService : IHostedService /// rather than hard-coded, so the bound /// configuration value is actually consumed. /// + /// Logging (ScadaBridge#120): akka.loggers names , so every + /// Akka ILoggingAdapter line is written to the host's Serilog pipeline (file sinks, node + /// enrichers, ExecutionId) instead of Akka's stdout-only DefaultLogger. + /// akka.loglevel stays INFO, so Akka's Debug chatter is filtered at the adapter as + /// before. + /// /// A downing-provider-class is always installed explicitly: Akka defaults /// to NoDowning, under which the downing configuration is inert and /// singletons never migrate on a hard crash or partition. Naming the provider is @@ -324,6 +330,8 @@ public class AkkaHostedService : IHostedService }} }} akka {{ + loggers = [{QuoteHocon(SerilogAkkaLogger.HoconTypeName)}] + loglevel = INFO extensions = [ ""Akka.Cluster.Tools.PublishSubscribe.DistributedPubSubExtensionProvider, Akka.Cluster.Tools"" ] diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs new file mode 100644 index 00000000..48454e12 --- /dev/null +++ b/src/ZB.MOM.WW.ScadaBridge.Host/Actors/SerilogAkkaLogger.cs @@ -0,0 +1,149 @@ +using Akka.Actor; +using Akka.Dispatch; +using Akka.Event; +using Serilog.Events; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using AkkaLogEvent = Akka.Event.LogEvent; +using AkkaLogLevel = Akka.Event.LogLevel; +using SerilogLog = Serilog.Log; + +namespace ZB.MOM.WW.ScadaBridge.Host.Actors; + +/// +/// The ActorSystem's logger (ScadaBridge#120): writes every Akka ILoggingAdapter line into +/// the host's Serilog pipeline, so those lines reach the file sinks and carry the node enrichers, +/// the same as lines written through Microsoft.Extensions.Logging. +/// +/// +/// Wiring. names this type in +/// akka.loggers. It replaces Akka's DefaultLogger, which wrote to stdout only. Lines go +/// to the static , which Program builds through +/// LoggerConfigurationFactory before the ActorSystem is created. ScadaBridge keeps its own +/// Serilog factory by design, so no Akka.Hosting or Akka.Logger.Serilog bridge is used. +/// Levels. Filtering is unchanged. akka.loglevel (INFO) still decides which lines +/// an adapter publishes, so Akka's Debug lifecycle chatter is never built. The Serilog minimum level +/// then applies as it does to every other line. Akka Debug, Info, Warning and Error map to Serilog +/// Debug, Information, Warning and Error. +/// Shape. SourceContext is the logging class's full name (for example +/// ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors.DataConnectionActor), so a +/// MinimumLevel.Override keyed on a namespace applies to Akka lines too. AkkaSource +/// carries the actor path. The message template is the adapter's own format string, so its +/// arguments become structured properties. The event keeps the timestamp Akka recorded when the +/// line was logged, not the time this actor wrote it. +/// ExecutionId. When the line was logged through an execution-aware adapter while an +/// execution was current, the message arrives as an . This +/// actor pushes that id onto the LogContext while it writes the line, so +/// Enrich.FromLogContext() adds ExecutionId as it would on the logging thread. +/// +public sealed class SerilogAkkaLogger : ActorBase, IRequiresMessageQueue +{ + /// The assembly-qualified type name akka.loggers uses to load this logger. + public static readonly string HoconTypeName = + $"{typeof(SerilogAkkaLogger).FullName}, {typeof(SerilogAkkaLogger).Assembly.GetName().Name}"; + + /// The property carrying the Akka log source (the actor path). + public const string AkkaSourceProperty = "AkkaSource"; + + private readonly Serilog.ILogger? _root; + + /// Creates the logger akka.loggers loads; it writes to . + public SerilogAkkaLogger() + { + } + + /// + /// Writes to instead of the static logger (tests). Public because Akka + /// creates actors through reflection, which does not find a non-public constructor. + /// + /// The Serilog logger to write to. + public SerilogAkkaLogger(Serilog.ILogger root) + { + _root = root; + } + + /// Handles the logger handshake and every published log event. + /// The message. + /// Whether the message was handled. + protected override bool Receive(object message) + { + switch (message) + { + case InitializeLogger: + Sender.Tell(new LoggerInitialized()); + return true; + case AkkaLogEvent logEvent: + // Read the static logger per event, not once: Program may replace it after startup. + Write(logEvent, _root ?? SerilogLog.Logger); + return true; + default: + return false; + } + } + + /// Writes one Akka log event to a Serilog logger. + /// The Akka log event. + /// The Serilog logger to write to. + internal static void Write(AkkaLogEvent logEvent, Serilog.ILogger root) + { + try + { + var level = ToSerilogLevel(logEvent.LogLevel()); + var logger = root; + if (!logger.IsEnabled(level)) + { + return; + } + + var (inner, executionId) = logEvent.Message is ExecutionTaggedLogMessage tagged + ? (tagged.Message, (Guid?)tagged.ExecutionId) + : (logEvent.Message, null); + + string template; + object?[] args; + if (inner is LogMessage logMessage) + { + template = logMessage.Format; + args = logMessage.Parameters().ToArray(); + } + else + { + template = "{AkkaMessage:l}"; + args = [inner?.ToString() ?? string.Empty]; + } + + logger = logger + .ForContext(Serilog.Core.Constants.SourceContextPropertyName, + logEvent.LogClass?.FullName ?? logEvent.LogSource) + .ForContext(AkkaSourceProperty, logEvent.LogSource); + + if (!logger.BindMessageTemplate(template, args, out var parsed, out var properties)) + { + return; + } + + var timestamp = new DateTimeOffset(DateTime.SpecifyKind(logEvent.Timestamp, DateTimeKind.Utc)); + var serilogEvent = new Serilog.Events.LogEvent(timestamp, level, logEvent.Cause, parsed, properties); + + using (ExecutionLogContext.Push(executionId)) + { + logger.Write(serilogEvent); + } + } + catch + { + // Deliberate swallow: a logger that throws would restart this actor and lose the lines + // behind it. Serilog itself never throws from Write; this guards the message unwrap. + } + } + + /// Maps an Akka log level to the matching Serilog level. + /// The Akka level. + /// The Serilog level. + internal static LogEventLevel ToSerilogLevel(AkkaLogLevel level) => level switch + { + AkkaLogLevel.DebugLevel => LogEventLevel.Debug, + AkkaLogLevel.InfoLevel => LogEventLevel.Information, + AkkaLogLevel.WarningLevel => LogEventLevel.Warning, + _ => LogEventLevel.Error, + }; +} diff --git a/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs b/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs index 6b9d537f..a53d4200 100644 --- a/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs +++ b/src/ZB.MOM.WW.ScadaBridge.Host/LoggerConfigurationFactory.cs @@ -96,7 +96,12 @@ public static class LoggerConfigurationFactory // launcher pushes onto LogContext, so lines written on a run's own call chain carry // the run's identity. See SiteRuntime ScriptRunLogScope for the (bounded) scope. .Enrich.FromLogContext() - .Enrich.With(new TraceContextEnricher()); + .Enrich.With(new TraceContextEnricher()) + // ScadaBridge#56: copies each line tagged with a TRACED execution's ExecutionId into that + // run's Flow Debugger step log (ScriptLog rows, source "node"). One volatile read and out + // when nothing is traced. Attached directly (never behind an async wrapper): its + // de-duplication guard is per thread. + .WriteTo.Sink(new ZB.MOM.WW.ScadaBridge.Commons.Observability.ExecutionLogCaptureSink()); } /// diff --git a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs index a294f53e..17a2e45a 100644 --- a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs +++ b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptExecutor.cs @@ -573,6 +573,11 @@ public class InboundScriptExecutor executionId: parentExecutionId, sourceNode: nodeIdentity?.NodeName); + // ScadaBridge#56: on a traced request, copy other central node-log lines tagged with its + // ExecutionId into its ScriptLog rows (source "node"). Declared inside the try so it is + // disposed before any catch block logs the request's outcome (already the inbound row). + using var nodeLines = scriptLogger.CaptureNodeLines(); + var context = new InboundScriptContext( parameters, route.WithDeadline(cts.Token) diff --git a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptLogger.cs b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptLogger.cs index 105206fa..a59fb2d1 100644 --- a/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.InboundAPI/InboundScriptLogger.cs @@ -3,6 +3,7 @@ using ZB.MOM.WW.Audit; using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; namespace ZB.MOM.WW.ScadaBridge.InboundAPI; @@ -33,14 +34,22 @@ namespace ZB.MOM.WW.ScadaBridge.InboundAPI; /// A method script may log from several concurrent tasks, so the counters are guarded. Nothing in /// this class is allowed to throw into the script: a debug observer must never fail the request. /// +/// +/// +/// Node lines (ScadaBridge#56): while is open on a traced request, +/// every other central node-log line tagged with the request's ExecutionId becomes a row with +/// source node, under the same line cap. This logger's own node forward is suppressed, so a +/// Log.* line is never copied twice. +/// /// -public sealed class InboundScriptLogger +public sealed class InboundScriptLogger : IExecutionLogTarget { /// Per-line message cap (design D7); longer messages are truncated with an ellipsis. public const int MaxMessageChars = 2_000; private const string SourceScript = "script"; private const string SourceRuntime = "runtime"; + private const string SourceNode = "node"; private readonly ILogger _logger; private readonly Action? _emit; @@ -54,6 +63,8 @@ public sealed class InboundScriptLogger private int _emitted; private int _dropped; private int _seq; + private IDisposable? _capture; + private bool _captureClosed; /// /// Initializes the per-execution logger. @@ -120,6 +131,9 @@ public sealed class InboundScriptLogger { if (_emit is null) return; + // The request is over: stop copying node lines first, so none lands after the closing row. + CloseCapture(); + int dropped; int seq; lock (_gate) @@ -142,9 +156,13 @@ public sealed class InboundScriptLogger try { - _logger.Log(level, exception, - "Script log [{LogLevel}] for inbound method {Method} (execution {ExecutionId}): {Message}", - levelName, _methodName, _executionId, text); + // Suppressed for the node-line sink (#56): this line becomes a "script" row below. + using (ExecutionLogCapture.Suppress()) + { + _logger.Log(level, exception, + "Script log [{LogLevel}] for inbound method {Method} (execution {ExecutionId}): {Message}", + levelName, _methodName, _executionId, text); + } } catch (Exception) { @@ -171,7 +189,72 @@ public sealed class InboundScriptLogger Emit(levelName, SourceScript, seq, text, exception); } - private void Emit(string level, string source, int seq, string message, Exception? exception) + /// + /// ScadaBridge#56: starts copying the central node-log lines tagged with this request's + /// ExecutionId into its rows (source node). A no-op on an untraced request or one + /// with no execution id. + /// + /// Internal on purpose: it is host plumbing, and a public member of the Log global + /// would be callable from script code. + /// A disposable that stops the copy; also stops it. + internal IDisposable CaptureNodeLines() + { + if (_emit is null || _executionId is not { } id) + { + return NoCapture.Instance; + } + + lock (_gate) + { + if (_captureClosed || _capture is not null) + { + return NoCapture.Instance; + } + + _capture = ExecutionLogCapture.Register(id, this); + return _capture; + } + } + + /// ScadaBridge#56: one tagged node-log line, from the per-execution sink. + /// The captured line. + void IExecutionLogTarget.Capture(CapturedLogLine line) + { + if (_emit is null) return; + + int seq; + lock (_gate) + { + if (_captureClosed) return; + if (_emitted >= _maxLines) + { + _dropped++; + return; + } + + _emitted++; + seq = ++_seq; + } + + Emit(line.Level, SourceNode, seq, Truncate(line.Message), line.Exception, line.Category, line.OccurredAtUtc); + } + + private void CloseCapture() + { + IDisposable? capture; + lock (_gate) + { + _captureClosed = true; + capture = _capture; + _capture = null; + } + + capture?.Dispose(); + } + + private void Emit( + string level, string source, int seq, string message, Exception? exception, + string? category = null, DateTime? occurredAtUtc = null) { AuditEvent evt; try @@ -180,6 +263,7 @@ public sealed class InboundScriptLogger AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered, + occurredAtUtc: occurredAtUtc, actor: _actor, target: _methodName, sourceNode: _sourceNode, @@ -191,7 +275,7 @@ public sealed class InboundScriptLogger errorMessage: exception?.Message, errorDetail: exception?.ToString(), requestSummary: message, - extra: new ScriptTraceExtra { LogLevel = level, LogSource = source, Seq = seq }.ToJson()); + extra: new ScriptTraceExtra { LogLevel = level, LogSource = source, LogCategory = category, Seq = seq }.ToJson()); } catch (Exception) { @@ -225,4 +309,13 @@ public sealed class InboundScriptLogger var keep = char.IsHighSurrogate(message[MaxMessageChars - 1]) ? MaxMessageChars - 1 : MaxMessageChars; return string.Concat(message.AsSpan(0, keep), "…"); } + + private sealed class NoCapture : IDisposable + { + public static readonly NoCapture Instance = new(); + + public void Dispose() + { + } + } } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs index fe5f36c8..cd36b9aa 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptLogger.cs @@ -1,4 +1,5 @@ using Microsoft.Extensions.Logging; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; @@ -11,7 +12,11 @@ namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; /// The already-clipped message text. /// The exception attached to the line, if any. /// The step row the line belongs to, or to fall back to the run's anchor row. -public delegate void ScriptLogEmitter(string level, string source, string message, Exception? exception, Guid? stepEventId); +/// On a node line (ScadaBridge#56): the logger category that wrote it; otherwise null. +/// When the line was logged; null means now. +public delegate void ScriptLogEmitter( + string level, string source, string message, Exception? exception, Guid? stepEventId, + string? category, DateTime? occurredAtUtc); /// /// Flow Debugger step logs (design 2026-09-09 D4/D5/D7): the Log global site scripts call. @@ -29,8 +34,14 @@ public delegate void ScriptLogEmitter(string level, string source, string messag /// /// Never throws into the script. A logging or emitting failure is swallowed: this is a /// debug observer, and a broken observer must not fail a production script run. +/// +/// Node lines (ScadaBridge#56). While is open, the +/// node-log sink () hands this logger every other line tagged +/// with the run's ExecutionId — the Instance Actor's, a DCL actor's, a protocol adapter's — +/// and each becomes a row with source node, under the same line cap. The logger's own node +/// forward is suppressed, so a Log.* line is never copied twice. /// -public sealed class ScriptLogger +public sealed class ScriptLogger : IExecutionLogTarget { /// Per-message character cap (design D7); longer messages are truncated and suffixed with an ellipsis. public const int MaxMessageChars = 2_000; @@ -45,6 +56,12 @@ public sealed class ScriptLogger private int _emitted; private int _dropped; + // Node-line registrations (ScadaBridge#56): the run's own id plus any inline shared-script child + // ids. Closed by FlushDropped (every run-end path) or by disposing the returned scopes. + private readonly List _captures = new(); + private readonly object _captureGate = new(); + private volatile bool _capturesClosed; + /// Creates the Log global for one script run. /// The node logger every line forwards to, traced or not. /// Row emitter; when the run is not traced (no rows are produced). @@ -103,7 +120,11 @@ public sealed class ScriptLogger message = Clip(message); try { - _logger.Log(level, exception, "[script] {Instance}/{Script} {ExecutionId}: {Message}", _instance, _script, _executionId, message); + // Suppressed for the node-line sink: this line becomes a "script" row below. + using (ExecutionLogCapture.Suppress()) + { + _logger.Log(level, exception, "[script] {Instance}/{Script} {ExecutionId}: {Message}", _instance, _script, _executionId, message); + } } catch { @@ -113,8 +134,70 @@ public sealed class ScriptLogger WriteRow(name, "script", message, exception); } + /// + /// ScadaBridge#56: starts copying the node-log lines tagged with + /// into this run's rows (source node). The site launcher opens it for the run's own id; an + /// inline shared script opens it for its child id, which shares this logger. A no-op on an + /// untraced run, so untraced runs never touch the registry. + /// + /// The execution whose tagged lines to copy. + /// Internal on purpose: it is host plumbing, and a public member of the Log global + /// would be callable from script code. + /// A disposable that stops the copy; also stops every copy. + internal IDisposable CaptureNodeLines(Guid executionId) + { + if (_emit is null) + { + return NoCapture.Instance; + } + + lock (_captureGate) + { + if (_capturesClosed) + { + return NoCapture.Instance; + } + + var registration = ExecutionLogCapture.Register(executionId, this); + _captures.Add(registration); + return registration; + } + } + + /// ScadaBridge#56: one tagged node-log line, from . + /// The captured line. + void IExecutionLogTarget.Capture(CapturedLogLine line) + { + // A line the sink looked up just before the run closed must not land after the closing row. + if (_capturesClosed) + { + return; + } + + WriteRow(line.Level, "node", line.Message, line.Exception, line.Category, line.OccurredAtUtc); + } + + /// Stops every node-line copy this logger opened. Idempotent. + private void CloseCaptures() + { + IDisposable[] open; + lock (_captureGate) + { + _capturesClosed = true; + open = _captures.ToArray(); + _captures.Clear(); + } + + foreach (var registration in open) + { + registration.Dispose(); + } + } + /// Emits one trace row, subject to the per-run line cap. - private void WriteRow(string level, string source, string message, Exception? exception) + private void WriteRow( + string level, string source, string message, Exception? exception, + string? category = null, DateTime? occurredAtUtc = null) { if (_emit is null) { @@ -129,7 +212,7 @@ public sealed class ScriptLogger try { - _emit(level, source, Clip(message), exception, TraceStepScope.Current); + _emit(level, source, Clip(message), exception, TraceStepScope.Current, category, occurredAtUtc); } catch { @@ -149,6 +232,9 @@ public sealed class ScriptLogger return; } + // The run is over: stop copying node lines first, so none lands after the closing row. + CloseCaptures(); + var n = Interlocked.Exchange(ref _dropped, 0); if (n == 0) { @@ -161,7 +247,7 @@ public sealed class ScriptLogger // so the two surfaces read the same in the step-log panel (only the option key differs). _emit("warn", "runtime", $"log line cap reached - {n} further log line(s) were not captured " + - $"(ScadaBridge:SiteRuntime:MaxLogLinesPerRun = {_maxLines})", null, null); + $"(ScadaBridge:SiteRuntime:MaxLogLinesPerRun = {_maxLines})", null, null, null, null); } catch { @@ -193,4 +279,13 @@ public sealed class ScriptLogger var keep = char.IsHighSurrogate(m[MaxMessageChars - 1]) ? MaxMessageChars - 1 : MaxMessageChars; return m[..keep] + "…"; } + + private sealed class NoCapture : IDisposable + { + public static readonly NoCapture Instance = new(); + + public void Dispose() + { + } + } } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs index fc01151f..ff0f0ebc 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLauncher.cs @@ -416,6 +416,13 @@ internal static class ScriptRunLauncher // ScadaBridge#56: stamp the run identity on the LogContext for the rest of the run. logScope = ScriptRunLogScope.Push(context.ExecutionId, instanceName, scriptName); + // ScadaBridge#56: while a TRACED run executes, other node-log lines tagged with its id (the + // Instance Actor's, the DCL's, an adapter's) are copied into its ScriptLog rows as source + // "node". Declared inside the try on purpose: it is disposed before any catch block runs, + // so the launcher's own timeout/failure lines (already the ScriptRun row) are never + // copied. FlushDropped closes it on the success path. A no-op when untraced. + using var nodeLines = context.Log.CaptureNodeLines(context.ExecutionId); + var globals = new ScriptGlobals { Instance = context, diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs index 9dff54e4..7e71e02e 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRunLogScope.cs @@ -34,7 +34,8 @@ internal static class ScriptRunLogScope /// A disposable that removes the three properties again. internal static IDisposable Push(Guid executionId, string instanceName, string scriptName) { - var a = LogContext.PushProperty(ExecutionIdProperty, executionId); + // Through ExecutionLogContext so ExecutionLogContext.Current tracks the run too (#120). + var a = ExecutionLogContext.Push(executionId)!; var b = LogContext.PushProperty(InstanceNameProperty, instanceName); var c = LogContext.PushProperty(ScriptNameProperty, scriptName); return new Scope(a, b, c); diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs index b72412bc..d1cb5718 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/ScriptRuntimeContext.cs @@ -603,11 +603,15 @@ public class ScriptRuntimeContext /// feed the warning straight back into this method. /// /// Level name as it appears on the wire: debug|info|warn|error. - /// Line origin: script (a Log.* call) or runtime. + /// Line origin: script (a Log.* call), runtime or node (ScadaBridge#56). /// The already-clipped message text. /// The exception attached to the line, if any. /// The owning step's EventId; null falls back to the run's anchor row (D2). - private void EmitLog(string level, string source, string message, Exception? exception, Guid? stepEventId) + /// On a node line (ScadaBridge#56): the logger category; otherwise null. + /// When the line was logged; null means now. + private void EmitLog( + string level, string source, string message, Exception? exception, Guid? stepEventId, + string? category, DateTime? occurredAtUtc) { if (!_isTraced) return; AuditEvent evt; @@ -615,7 +619,7 @@ public class ScriptRuntimeContext { evt = ScadaBridgeAuditEventFactory.Create( AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered, - occurredAtUtc: DateTime.UtcNow, + occurredAtUtc: occurredAtUtc is { } at ? DateTime.SpecifyKind(at, DateTimeKind.Utc) : DateTime.UtcNow, actor: _sourceScript, target: _logTarget, sourceNode: _sourceNode, executionId: _executionId, parentExecutionId: _parentExecutionId, sourceSiteId: string.IsNullOrEmpty(_siteId) ? null : _siteId, @@ -626,6 +630,7 @@ public class ScriptRuntimeContext { LogLevel = level, LogSource = source, + LogCategory = category, StepEventId = stepEventId, Seq = Interlocked.Increment(ref _logSeq), }.ToJson()); @@ -1468,6 +1473,11 @@ public class ScriptRuntimeContext // ExecutionId, so its audit rows chain under the calling run. var childContext = _context.CreateChildContextForSharedScript(nextDepth); + // ScadaBridge#56: the shared script's requests are stamped with ITS execution id, so the + // node lines they cause carry that id. Copy them into the shared Log (the caller's rows), + // exactly where the shared script's own Log.* lines go. No-op when untraced. + using var childNodeLines = childContext.Log.CaptureNodeLines(childContext.ExecutionId); + return await _library.ExecuteAsync( scriptName, childContext, ScriptArgs.Normalize(parameters), cancellationToken).ConfigureAwait(false); } diff --git a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs index a8925668..6917cd34 100644 --- a/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs +++ b/src/ZB.MOM.WW.ScadaBridge.SiteRuntime/Scripts/TraceCapturingLogger.cs @@ -1,4 +1,5 @@ using Microsoft.Extensions.Logging; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; @@ -68,7 +69,12 @@ public sealed class TraceCapturingLogger : ILogger // upward for trace capture, so the node's own minimum level must be re-checked here. if (_inner.IsEnabled(level)) { - _inner.Log(level, eventId, state, exception, formatter); + // Suppressed for the node-line sink (ScadaBridge#56): this decorator already turns the + // entry into a "runtime" row below (or deliberately drops it, below Information). + using (ExecutionLogCapture.Suppress()) + { + _inner.Log(level, eventId, state, exception, formatter); + } } if (level < LogLevel.Information || level == LogLevel.None) diff --git a/tests/ZB.MOM.WW.ScadaBridge.CLI.Tests/FlowDebugCommandsTests.cs b/tests/ZB.MOM.WW.ScadaBridge.CLI.Tests/FlowDebugCommandsTests.cs index b0f8a053..68a7fdc9 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.CLI.Tests/FlowDebugCommandsTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.CLI.Tests/FlowDebugCommandsTests.cs @@ -423,6 +423,44 @@ public class FlowDebugCommandsTests Assert.DoesNotContain("at Z", projected); } + /// + /// ScadaBridge#56: node lines are not on a step (the logs column does not count them); with + /// --show-logs they print as one trailing block, each naming its logger without the namespace. + /// + [Fact] + public void Projection_ShowLogs_PrintsNodeLinesAsATrailingBlock() + { + var root = Guid.NewGuid(); + var t0 = new DateTime(2026, 11, 10, 10, 0, 0, DateTimeKind.Utc); + var events = new List + { + ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptRun, AuditStatus.Delivered, + occurredAtUtc: t0, target: "Runner", executionId: root, sourceSiteId: "site-a", + sourceInstanceId: "M1", sourceScript: "Runner", durationMs: 50), + ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered, + occurredAtUtc: t0.AddMilliseconds(5), target: "Runner", executionId: root, requestSummary: "Writing to tag T1", + extra: new ScriptTraceExtra + { + LogLevel = "warn", LogSource = "node", Seq = 1, + LogCategory = "ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors.DataConnectionActor", + }.ToJson()), + }; + var json = JsonSerializer.Serialize( + new FlowDebugRunResult(root, true, null, null, events, false, new DateTimeOffset(t0), new DateTimeOffset(t0.AddSeconds(1))), + CamelCase); + + using var plain = JsonDocument.Parse(FlowDebugTableProjection.ProjectEvents(json)); + var row = Assert.Single(plain.RootElement.EnumerateArray()); + Assert.Equal(0, row.GetProperty("logs").GetInt32()); + + using var shown = JsonDocument.Parse(FlowDebugTableProjection.ProjectEvents(json, showLogs: true)); + var rows = shown.RootElement.EnumerateArray().ToList(); + Assert.Equal(3, rows.Count); + Assert.Equal("node log (1 line):", rows[1].GetProperty("note").GetString()); + Assert.Equal($" {t0.AddMilliseconds(5):HH:mm:ss.fff} WARN [DataConnectionActor] Writing to tag T1", + rows[2].GetProperty("note").GetString()); + } + /// Verifies that hiding logs omits the log and exception detail lines. [Fact] public void Projection_ShowLogsFalse_OmitsLogAndExceptionDetailLines() diff --git a/tests/ZB.MOM.WW.ScadaBridge.CentralUI.Tests/Deployment/FlowNodeLogPanelTests.cs b/tests/ZB.MOM.WW.ScadaBridge.CentralUI.Tests/Deployment/FlowNodeLogPanelTests.cs new file mode 100644 index 00000000..a2157b84 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.CentralUI.Tests/Deployment/FlowNodeLogPanelTests.cs @@ -0,0 +1,103 @@ +using Bunit; +using ZB.MOM.WW.ScadaBridge.CentralUI.Components.Deployment; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; + +namespace ZB.MOM.WW.ScadaBridge.CentralUI.Tests.Deployment; + +/// +/// ScadaBridge#56: the Flow Debugger's node-log section lists the lines other actors wrote for each +/// traced execution — grouped per execution under that execution's run step, with level filtering and +/// the logger category — and renders nothing when the graph has no node lines. +/// +public class FlowNodeLogPanelTests : BunitContext +{ + private static readonly DateTimeOffset T0 = new(2026, 11, 10, 12, 0, 0, TimeSpan.Zero); + + private static FlowStep Run(Guid execution, string title) + => new(Guid.NewGuid(), execution, null, FlowStepKind.ScriptRun, FlowLane.Site, title, null, T0, 10, + FlowStepOutcome.Ok, null, null, null, "site-a", "node-a", "M1", title, null); + + private static FlowLogLine Node(Guid execution, string level, string message, int ms, + string category = "ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors.DataConnectionActor", + string? exceptionMessage = null) + => new(Guid.NewGuid(), execution, T0.AddMilliseconds(ms), level, FlowLogLine.NodeSource, message, + exceptionMessage, exceptionMessage is null ? null : "System.Exception: " + exceptionMessage, null, ms, category); + + private static FlowGraph Graph(IReadOnlyList steps, IReadOnlyList? nodeLogs) + => new(steps, [], Predicted: false, Truncated: false, NodeLogs: nodeLogs); + + /// No node lines (or no graph): the section is not rendered at all. + [Fact] + public void NoNodeLines_RendersNothing() + { + var execution = Guid.NewGuid(); + Assert.Empty(Render(p => p.Add(x => x.Graph, Graph([Run(execution, "Runner")], null))) + .FindAll("[data-test=flow-nodelog-panel]")); + Assert.Empty(Render().FindAll("[data-test=flow-nodelog-panel]")); + } + + /// Lines are grouped per execution, titled by its run step, with short category, level and counts. + [Fact] + public void Lines_AreGroupedPerExecution_UnderTheRunStep() + { + var a = Guid.NewGuid(); + var b = Guid.NewGuid(); + var graph = Graph([Run(a, "OnRecipe"), Run(b, "SharedHelper")], + [ + Node(a, "debug", "Writing to tag T1", 1), + Node(b, "warn", "tag T2 bad quality", 2, category: "ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors.InstanceActor"), + Node(a, "error", "write failed", 3, exceptionMessage: "timeout"), + ]); + + var cut = Render(p => p.Add(x => x.Graph, graph)); + + Assert.Equal("3 lines · 1 error · 1 warning · 1 info/debug", cut.Find("[data-test=flow-nodelog-count]").TextContent); + var groups = cut.FindAll("[data-test=flow-nodelog-execution]"); + Assert.Equal(2, groups.Count); + Assert.Contains("OnRecipe", groups[0].TextContent); + Assert.Contains(a.ToString(), groups[0].TextContent); + var aRows = groups[0].QuerySelectorAll("tbody tr"); + Assert.Equal(2, aRows.Length); + Assert.Contains("DataConnectionActor", aRows[0].TextContent); + Assert.DoesNotContain("ZB.MOM.WW", aRows[0].TextContent); + Assert.Contains("timeout", aRows[1].TextContent); + Assert.Contains("InstanceActor", groups[1].TextContent); + Assert.Contains("tag T2 bad quality", groups[1].TextContent); + } + + /// Warn + hides debug/info lines; an execution left with none says so; All restores them. + [Fact] + public void WarnPlusFilter_HidesLowLevels() + { + var a = Guid.NewGuid(); + var b = Guid.NewGuid(); + var graph = Graph([Run(a, "OnRecipe"), Run(b, "Other")], + [Node(a, "info", "connected", 1), Node(a, "warn", "slow write", 2), Node(b, "debug", "chatter", 3)]); + var cut = Render(p => p.Add(x => x.Graph, graph)); + + cut.Find("[data-test=flow-nodelog-filter-warn]").Click(); + + var groups = cut.FindAll("[data-test=flow-nodelog-execution]"); + Assert.Equal("warn", Assert.Single(groups[0].QuerySelectorAll("tbody tr")).GetAttribute("data-level")); + Assert.NotNull(groups[1].QuerySelector("[data-test=flow-nodelog-none-shown]")); + + cut.Find("[data-test=flow-nodelog-filter-all]").Click(); + Assert.Equal(3, cut.FindAll("[data-test=flow-nodelog-lines] tbody tr").Count); + } + + /// Clicking the execution's title selects its run step. + [Fact] + public void ExecutionTitle_SelectsItsRunStep() + { + var a = Guid.NewGuid(); + var run = Run(a, "OnRecipe"); + FlowStep? selected = null; + var cut = Render(p => p + .Add(x => x.Graph, Graph([run], [Node(a, "warn", "slow", 1)])) + .Add(x => x.OnSelectStep, s => selected = s)); + + cut.Find("[data-test=flow-nodelog-step]").Click(); + + Assert.Same(run, selected); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Debugging/FlowGraphBuilderLogLineTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Debugging/FlowGraphBuilderLogLineTests.cs index 10eaacd5..dfffd365 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Debugging/FlowGraphBuilderLogLineTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Debugging/FlowGraphBuilderLogLineTests.cs @@ -213,4 +213,46 @@ public class FlowGraphBuilderLogLineTests Assert.Single(call.Logs!); Assert.Null(StepOf(graph, FlowStepKind.ScriptRun).Logs); } + + private static AuditEvent NodeLine(Guid execution, int ms, int? seq, string message, string category = "Acme.Dcl") => + ScadaBridgeAuditEventFactory.Create(AuditChannel.ScriptTrace, AuditKind.ScriptLog, AuditStatus.Delivered, + occurredAtUtc: T0.AddMilliseconds(ms), actor: "SomeScript", target: "SomeScript", sourceNode: "node-a", + executionId: execution, sourceSiteId: "site-a", sourceInstanceId: "M1", requestSummary: message, + extra: new ScriptTraceExtra { LogLevel = "warn", LogSource = "node", LogCategory = category, Seq = seq }.ToJson()); + + /// + /// ScadaBridge#56: node lines are listed on the graph in time order (seq breaking ties), never folded + /// onto a step — not even the anchor — and never counted as unattached, while script lines still fold. + /// + [Fact] + public void NodeLines_AreListedOnTheGraph_NotFoldedOntoSteps() + { + var execution = Guid.NewGuid(); + var orphan = Guid.NewGuid(); // an execution with no step at all + + var graph = FlowGraphBuilder.Build( + [ + Run(execution), Line(execution), + NodeLine(execution, ms: 30, seq: 2, message: "late"), + NodeLine(execution, ms: 20, seq: 9, message: "early-b"), + NodeLine(execution, ms: 20, seq: 1, message: "early-a"), + NodeLine(orphan, ms: 40, seq: 1, message: "orphan"), + ]); + + Assert.Equal(["early-a", "early-b", "late", "orphan"], graph.NodeLogs!.Select(l => l.Message)); + Assert.All(graph.NodeLogs!, l => Assert.True(l.IsNodeLine)); + Assert.Equal("Acme.Dcl", graph.NodeLogs![0].Category); + var anchorLogs = StepOf(graph, FlowStepKind.ScriptRun).Logs!; + Assert.Equal("hello", Assert.Single(anchorLogs).Message); + Assert.Equal(0, graph.UnattachedLogLines); + } + + /// A trace with no node lines has a null , including a step-less one. + [Fact] + public void NoNodeLines_LeavesNodeLogsNull() + { + var execution = Guid.NewGuid(); + Assert.Null(FlowGraphBuilder.Build([Run(execution), Line(execution)]).NodeLogs); + Assert.Single(FlowGraphBuilder.Build([NodeLine(execution, 1, 1, "only")]).NodeLogs!); + } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogCaptureTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogCaptureTests.cs new file mode 100644 index 00000000..02a62a3f --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogCaptureTests.cs @@ -0,0 +1,148 @@ +using System.Collections.Concurrent; +using Serilog; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; + +namespace ZB.MOM.WW.ScadaBridge.Commons.Tests.Observability; + +/// +/// ScadaBridge#56: the per-execution sink copies a line to the target registered for the line's +/// ExecutionId — and to nothing else. Each test uses fresh ids, because the registry is +/// process-wide and other tests may register concurrently. +/// +public class ExecutionLogCaptureTests +{ + private sealed class Target : IExecutionLogTarget + { + public ConcurrentQueue Lines { get; } = new(); + public Action? OnCapture { get; init; } + + public void Capture(CapturedLogLine line) + { + Lines.Enqueue(line); + OnCapture?.Invoke(line); + } + } + + private static Serilog.ILogger Node() => new LoggerConfiguration() + .MinimumLevel.Information() + .Enrich.FromLogContext() + .WriteTo.Sink(new ExecutionLogCaptureSink()) + .CreateLogger(); + + /// A line tagged with a registered id reaches its target with level, category, text, exception and time. + [Fact] + public void TaggedLine_ReachesItsTarget() + { + var node = Node().ForContext("SourceContext", "Acme.InstanceActor"); + var id = Guid.NewGuid(); + var target = new Target(); + using var registration = ExecutionLogCapture.Register(id, target); + + using (ExecutionLogContext.Push(id)) + node.Warning(new InvalidOperationException("bad"), "wrote {Tag}", "T1"); + + var line = Assert.Single(target.Lines); + Assert.Equal("warn", line.Level); + Assert.Equal("Acme.InstanceActor", line.Category); + Assert.Equal("wrote \"T1\"", line.Message); + Assert.Equal("bad", line.Exception!.Message); + Assert.Equal(DateTimeKind.Utc, line.OccurredAtUtc.Kind); + Assert.True(ExecutionLogCapture.HasTargets); + } + + /// Untagged lines, lines of another execution, and lines below the node's level are not captured. + [Fact] + public void UntaggedOrOtherOrFilteredLines_AreNotCaptured() + { + var node = Node(); + var id = Guid.NewGuid(); + var target = new Target(); + using var registration = ExecutionLogCapture.Register(id, target); + + node.Information("untagged"); + using (ExecutionLogContext.Push(Guid.NewGuid())) + node.Information("other execution"); + using (ExecutionLogContext.Push(id)) + node.Debug("below the node minimum"); + + Assert.Empty(target.Lines); + } + + /// A line written inside (already a trace row) is skipped. + [Fact] + public void SuppressedLine_IsNotCaptured() + { + var node = Node(); + var id = Guid.NewGuid(); + var target = new Target(); + using var registration = ExecutionLogCapture.Register(id, target); + + using (ExecutionLogContext.Push(id)) + { + using (ExecutionLogCapture.Suppress()) + node.Information("already a row"); + node.Information("captured"); + } + + Assert.Equal("captured", Assert.Single(target.Lines).Message); + } + + /// A target that logs for the same execution while capturing does not loop back into itself. + [Fact] + public void TargetThatLogs_DoesNotRecapture() + { + var node = Node(); + var id = Guid.NewGuid(); + // Logs once only, so a broken guard fails this test instead of overflowing the stack. + var logged = 0; + var target = new Target { OnCapture = _ => { if (Interlocked.Increment(ref logged) == 1) node.Warning("emit failed"); } }; + using var registration = ExecutionLogCapture.Register(id, target); + + using (ExecutionLogContext.Push(id)) + node.Information("first"); + + Assert.Equal("first", Assert.Single(target.Lines).Message); + } + + /// A line logged on another thread that re-pushed the id (an actor serving the run) is captured. + /// A task that represents the asynchronous operation. + [Fact] + public async Task LineOnAnotherThread_WithTheIdRepushed_IsCaptured() + { + var node = Node(); + var id = Guid.NewGuid(); + var target = new Target(); + using var registration = ExecutionLogCapture.Register(id, target); + + await Task.Factory.StartNew(() => + { + using (ExecutionLogContext.Push(id)) + node.Information("from an actor thread"); + }, CancellationToken.None, TaskCreationOptions.LongRunning, TaskScheduler.Default); + + Assert.Equal("from an actor thread", Assert.Single(target.Lines).Message); + } + + /// Disposing removes the registration; a duplicate registration is ignored and its disposal harmless. + [Fact] + public void Dispose_Unregisters_AndDuplicateIsIgnored() + { + var node = Node(); + var id = Guid.NewGuid(); + var first = new Target(); + var second = new Target(); + var registration = ExecutionLogCapture.Register(id, first); + ExecutionLogCapture.Register(id, second).Dispose(); // duplicate: no-op, must not remove the first + + Assert.True(ExecutionLogCapture.TryGetTarget(id, out var found)); + Assert.Same(first, found); + + registration.Dispose(); + registration.Dispose(); + Assert.False(ExecutionLogCapture.TryGetTarget(id, out _)); + using (ExecutionLogContext.Push(id)) + node.Information("after"); + Assert.Empty(first.Lines); + Assert.Empty(second.Lines); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs index b04e37c9..f6e2be52 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Commons.Tests/Observability/ExecutionLogContextTests.cs @@ -102,4 +102,29 @@ public class ExecutionLogContextTests Assert.Equal(child.ToString(), events[1].Properties[ExecutionLogContext.ExecutionIdProperty].ToString().Trim('"')); Assert.False(events[2].Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty)); } + + /// + /// ScadaBridge#120: mirrors the pushed id, follows + /// nesting, and is restored when each push is disposed (twice is harmless). + /// + [Fact] + public void Current_TracksPushes_AndIsRestoredOnDispose() + { + var outer = Guid.NewGuid(); + var inner = Guid.NewGuid(); + Assert.Null(ExecutionLogContext.Current); + + var a = ExecutionLogContext.Push(outer); + Assert.Equal(outer, ExecutionLogContext.Current); + var b = ExecutionLogContext.Push(inner); + Assert.Equal(inner, ExecutionLogContext.Current); + Assert.Null(ExecutionLogContext.Push(null)); // a null push changes nothing + Assert.Equal(inner, ExecutionLogContext.Current); + + b!.Dispose(); + b.Dispose(); + Assert.Equal(outer, ExecutionLogContext.Current); + a!.Dispose(); + Assert.Null(ExecutionLogContext.Current); + } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionAwareLoggingTests.cs b/tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionAwareLoggingTests.cs new file mode 100644 index 00000000..20326f54 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests/Actors/ExecutionAwareLoggingTests.cs @@ -0,0 +1,131 @@ +using Akka.Actor; +using Akka.Event; +using Akka.TestKit.Xunit2; +using NSubstitute; +using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Protocol; +using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.DataConnection; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Actors; +using ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Logging; +using ZB.MOM.WW.ScadaBridge.HealthMonitoring; + +namespace ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Tests.Actors; + +/// +/// ScadaBridge#120: the DCL actors' own Akka _log lines record the execution id of the +/// message being served, so the host's Serilog logger actor can tag them although it writes them +/// on another thread. +/// +public class ExecutionAwareLoggingTests : TestKit +{ + /// Debug level so the DCL's write-path Debug line is published. + public ExecutionAwareLoggingTests() : base("akka.loglevel = DEBUG") + { + } + + private sealed record LogUnder(Guid? Id); + + private sealed class Probe : ReceiveActor + { + private readonly ILoggingAdapter _log = ExecutionAwareLogging.GetLogger(Context); + + public Probe() + { + Receive(m => + { + var id = m.Id; + using (ExecutionLogContext.Push(id)) + _log.Info("probe {0}", id?.ToString() ?? "none"); + }); + Receive(_ => _log.Debug("debug {0}", "x")); + } + } + + /// A line logged inside an execution's push is published wrapped with that id; its text is unchanged. + [Fact] + public void LineInsideAPush_IsTaggedWithTheExecutionId_TextUnchanged() + { + var events = CreateTestProbe(); + Sys.EventStream.Subscribe(events.Ref, typeof(Info)); + var id = Guid.NewGuid(); + + Sys.ActorOf(Props.Create(() => new Probe())).Tell(new LogUnder(id)); + + var info = events.FishForMessage(i => i.Message.ToString()!.StartsWith("probe", StringComparison.Ordinal)); + var tagged = Assert.IsType(info.Message); + Assert.Equal(id, tagged.ExecutionId); + Assert.Equal($"probe {id}", info.Message.ToString()); + Assert.IsAssignableFrom(tagged.Message); + } + + /// With no execution current, the line is published exactly as Context.GetLogger() would publish it. + [Fact] + public void LineOutsideAPush_IsPublishedUnwrapped() + { + var events = CreateTestProbe(); + Sys.EventStream.Subscribe(events.Ref, typeof(Info)); + + Sys.ActorOf(Props.Create(() => new Probe())).Tell(new LogUnder(null)); + + var info = events.FishForMessage(i => i.Message.ToString()!.StartsWith("probe", StringComparison.Ordinal)); + Assert.IsAssignableFrom(info.Message); + Assert.Equal("probe none", info.Message.ToString()); + } + + /// The adapter honours akka.loglevel: a Debug line is not published once the bus is at Info. + [Fact] + public void DisabledLevel_PublishesNothing() + { + Sys.EventStream.SetLogLevel(Akka.Event.LogLevel.InfoLevel); + var events = CreateTestProbe(); + Sys.EventStream.Subscribe(events.Ref, typeof(Debug)); + + Sys.ActorOf(Props.Create(() => new Probe())).Tell("debug"); + + events.ExpectNoMsg(TimeSpan.FromMilliseconds(300)); + } + + /// + /// End to end on the DCL: the DataConnectionActor's own write-path Debug line, logged while it + /// serves a correlated WriteTagRequest, is tagged with the request's execution id; an + /// uncorrelated write's line is not (control). + /// + /// A task that represents the asynchronous operation. + [Fact] + public async Task DataConnectionActor_WritePathLine_IsTagged_UncorrelatedIsNot() + { + var adapter = Substitute.For(); + adapter.ConnectAsync(Arg.Any>(), Arg.Any()) + .Returns(Task.CompletedTask); + adapter.WriteAsync(Arg.Any(), Arg.Any(), Arg.Any()) + .Returns(Task.FromResult(new WriteResult(true, null))); + var options = new DataConnectionOptions + { + ReconnectInterval = TimeSpan.FromMilliseconds(100), + WriteTimeout = TimeSpan.FromSeconds(5), + SeedReadMaxAttempts = 1, + SeedReadRetryDelay = TimeSpan.FromMilliseconds(10), + }; + var actor = Sys.ActorOf(Props.Create(() => new DataConnectionActor( + "akka-tag", adapter, options, Substitute.For(), + Substitute.For(), "OpcUa")), "akka-tag"); + AwaitCondition(() => adapter.ReceivedCalls().Any(c => c.GetMethodInfo().Name == "ConnectAsync"), + TimeSpan.FromSeconds(3)); + await Task.Delay(200); + + var events = CreateTestProbe(); + Sys.EventStream.Subscribe(events.Ref, typeof(Debug)); + var id = Guid.NewGuid(); + + actor.Tell(new WriteTagRequest("c1", "akka-tag", "tagT", 1, DateTimeOffset.UtcNow, id)); + Assert.True(ExpectMsg(TimeSpan.FromSeconds(5)).Success); + var tagged = events.FishForMessage(d => d.Message.ToString()!.Contains("Writing to tag tagT", StringComparison.Ordinal)); + Assert.Equal(id, Assert.IsType(tagged.Message).ExecutionId); + + actor.Tell(new WriteTagRequest("c2", "akka-tag", "tagU", 1, DateTimeOffset.UtcNow)); + Assert.True(ExpectMsg(TimeSpan.FromSeconds(5)).Success); + var plain = events.FishForMessage(d => d.Message.ToString()!.Contains("Writing to tag tagU", StringComparison.Ordinal)); + Assert.IsNotType(plain.Message); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs index 7bca937e..f8d4b374 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/LoggerConfigurationTests.cs @@ -186,4 +186,32 @@ public class LoggerConfigurationTests // a recognised level, so ParseLevel is silent too.) Assert.Empty(writer.ToString()); } + + private sealed class CollectingTarget : ZB.MOM.WW.ScadaBridge.Commons.Observability.IExecutionLogTarget + { + public List Lines { get; } = new(); + public void Capture(ZB.MOM.WW.ScadaBridge.Commons.Observability.CapturedLogLine line) => Lines.Add(line); + } + + /// + /// ScadaBridge#56: the host pipeline carries the per-execution capture sink, so a line tagged with + /// a registered (traced) execution reaches that execution's step log. + /// + [Fact] + public void Build_IncludesTheExecutionCaptureSink() + { + var configuration = new ConfigurationBuilder().AddInMemoryCollection(new Dictionary()).Build(); + using var logger = LoggerConfigurationFactory.Build(configuration, "Site", "site-a", "node1", new StringWriter()) + .CreateLogger(); + var id = Guid.NewGuid(); + var target = new CollectingTarget(); + + using (ZB.MOM.WW.ScadaBridge.Commons.Observability.ExecutionLogCapture.Register(id, target)) + using (ZB.MOM.WW.ScadaBridge.Commons.Observability.ExecutionLogContext.Push(id)) + { + logger.Warning("tagged line"); + } + + Assert.Equal("tagged line", Assert.Single(target.Lines).Message); + } } diff --git a/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs new file mode 100644 index 00000000..06be146f --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.Host.Tests/SerilogAkkaLoggerTests.cs @@ -0,0 +1,231 @@ +using System.Collections.Concurrent; +using Akka.Actor; +using Akka.Configuration; +using Akka.Event; +using Akka.TestKit.Xunit2; +using Serilog; +using Serilog.Core; +using Serilog.Events; +using ZB.MOM.WW.ScadaBridge.ClusterInfrastructure; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ZB.MOM.WW.ScadaBridge.DataConnectionLayer.Logging; +using ZB.MOM.WW.ScadaBridge.Host.Actors; +using AkkaLogEvent = Akka.Event.LogEvent; +using SerilogLogEvent = Serilog.Events.LogEvent; + +namespace ZB.MOM.WW.ScadaBridge.Host.Tests; + +/// +/// ScadaBridge#120: Akka ILoggingAdapter lines reach the host's Serilog pipeline, with the +/// node enrichers and, for an execution-aware adapter, the ExecutionId of the message the +/// actor was serving. +/// +public class SerilogAkkaLoggerTests : TestKit +{ + private sealed class CaptureSink : ILogEventSink + { + public ConcurrentQueue Events { get; } = new(); + public void Emit(SerilogLogEvent logEvent) => Events.Enqueue(logEvent); + } + + /// An actor that logs through the execution-aware adapter while serving a message. + private sealed class LoggingActor : ReceiveActor + { + private readonly ILoggingAdapter _log = ExecutionAwareLogging.GetLogger(Context); + + public LoggingActor() + { + Receive<(Guid? Id, string Text)>(m => + { + using (ExecutionLogContext.Push(m.Id)) + _log.Warning("actor line {0}", m.Text); + Sender.Tell("done"); + }); + } + } + + private readonly CaptureSink _sink = new(); + private readonly Serilog.ILogger _serilog; + + /// + /// The system keeps Akka's default logger (TestKit's); each test that needs the bridge spawns a + /// over a capturing pipeline that mirrors the host's + /// LoggerConfigurationFactory (Enrich.FromLogContext plus a node property). + /// + public SerilogAkkaLoggerTests() : base("akka.loglevel = INFO") + { + _serilog = new LoggerConfiguration() + .MinimumLevel.Information() + .Enrich.WithProperty("NodeRole", "site-a") + .Enrich.FromLogContext() + .WriteTo.Sink(_sink) + .CreateLogger(); + } + + private void StartBridge() + { + var bridge = Sys.ActorOf(Props.Create(() => new SerilogAkkaLogger(_serilog))); + Sys.EventStream.Subscribe(bridge, typeof(AkkaLogEvent)); + } + + private SerilogLogEvent AwaitLine(string fragment) + { + SerilogLogEvent? found = null; + AwaitCondition(() => + { + found = _sink.Events.FirstOrDefault(e => e.RenderMessage().Contains(fragment, StringComparison.Ordinal)); + return found is not null; + }, TimeSpan.FromSeconds(5)); + return found!; + } + + private static string? Scalar(SerilogLogEvent e, string name) + => e.Properties.TryGetValue(name, out var v) && v is ScalarValue { Value: { } x } ? x.ToString() : null; + + /// An Akka line reaches Serilog with its level, class, actor path, structured args and node enrichers. + [Fact] + public void AkkaLine_ReachesSerilog_WithSourceContextAndEnrichers() + { + StartBridge(); + var actor = Sys.ActorOf(Props.Create(() => new LoggingActor()), "plain-logger"); + + actor.Tell(((Guid?)null, "alpha")); + ExpectMsg("done"); + + var line = AwaitLine("actor line"); + Assert.Equal(LogEventLevel.Warning, line.Level); + Assert.Equal(typeof(LoggingActor).FullName, Scalar(line, "SourceContext")); + Assert.Contains("plain-logger", Scalar(line, SerilogAkkaLogger.AkkaSourceProperty)); + Assert.Equal("site-a", Scalar(line, "NodeRole")); + Assert.Equal("actor line \"alpha\"", line.RenderMessage()); + // The adapter's argument is a structured property, not baked into the text. + Assert.Equal("alpha", Scalar(line, "0")); + Assert.False(line.Properties.ContainsKey(ExecutionLogContext.ExecutionIdProperty)); + } + + /// + /// The line logged while an execution was current carries that id, although Serilog writes it on + /// the logger actor's thread, where the logging actor's LogContext is not in effect. + /// + [Fact] + public void ExecutionAwareLine_CarriesTheExecutionId_AcrossTheLoggerHop() + { + StartBridge(); + var actor = Sys.ActorOf(Props.Create(() => new LoggingActor())); + var id = Guid.NewGuid(); + + actor.Tell(((Guid?)id, "beta")); + ExpectMsg("done"); + + Assert.Equal(id.ToString(), Scalar(AwaitLine("beta"), ExecutionLogContext.ExecutionIdProperty)); + } + + /// The Akka timestamp is kept, not replaced by the time the logger actor wrote the line. + [Fact] + public void Write_KeepsTheAkkaTimestamp_AndMapsEveryLevel() + { + var serilog = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(_sink).CreateLogger(); + var then = new DateTime(2026, 1, 2, 3, 4, 5, DateTimeKind.Utc); + + foreach (var (evt, expected) in new (AkkaLogEvent, LogEventLevel)[] + { + (new Debug("src", typeof(LoggingActor), "d-line"), LogEventLevel.Debug), + (new Info("src", typeof(LoggingActor), "i-line"), LogEventLevel.Information), + (new Warning("src", typeof(LoggingActor), "w-line"), LogEventLevel.Warning), + (new Error(new InvalidOperationException("boom"), "src", typeof(LoggingActor), "e-line"), LogEventLevel.Error), + }) + { + typeof(AkkaLogEvent).GetProperty(nameof(AkkaLogEvent.Timestamp))!.SetValue(evt, then); + SerilogAkkaLogger.Write(evt, serilog); + var line = _sink.Events.Single(e => e.RenderMessage().Contains(evt.Message.ToString()!, StringComparison.Ordinal)); + Assert.Equal(expected, line.Level); + Assert.Equal(new DateTimeOffset(then), line.Timestamp); + } + + Assert.Equal("boom", _sink.Events.Single(e => e.Level == LogEventLevel.Error).Exception!.Message); + } + + /// The Serilog minimum level applies to Akka lines as it does to every other line. + [Fact] + public void Write_BelowTheSerilogMinimum_IsDropped() + { + // _serilog's minimum is Information. + SerilogAkkaLogger.Write(new Debug("src", typeof(LoggingActor), "debug-only"), _serilog); + SerilogAkkaLogger.Write(new Info("src", typeof(LoggingActor), "info-kept"), _serilog); + + Assert.DoesNotContain(_sink.Events, e => e.RenderMessage().Contains("debug-only", StringComparison.Ordinal)); + Assert.Contains(_sink.Events, e => e.RenderMessage().Contains("info-kept", StringComparison.Ordinal)); + } + + /// + /// The HOCON the host builds names this logger and keeps akka.loglevel at INFO, so Akka's + /// Debug lifecycle chatter stays filtered at the adapter (no volume change from the bridge). + /// + [Fact] + public void BuildHocon_NamesTheSerilogLogger_AndKeepsInfoLevel() + { + var hocon = AkkaHostedService.BuildHocon( + new NodeOptions { Role = "Site", NodeHostname = "n", RemotingPort = 8082 }, + new ClusterOptions { SeedNodes = ["akka.tcp://scadabridge@n:8082"], SplitBrainResolverStrategy = "auto-down" }, + ["Site"], TimeSpan.FromSeconds(5), TimeSpan.FromSeconds(15)); + + var config = ConfigurationFactory.ParseString(hocon); + Assert.Equal([SerilogAkkaLogger.HoconTypeName], config.GetStringList("akka.loggers")); + Assert.Equal("INFO", config.GetString("akka.loglevel")); + } + + /// + /// The type name in akka.loggers resolves and the logger completes Akka's startup + /// handshake — a wrong name or a missing LoggerInitialized reply fails system creation. + /// + [Fact] + public async Task ActorSystem_StartsWithTheSerilogLoggerConfigured() + { + var config = ConfigurationFactory.ParseString( + $"akka.loggers = [\"{SerilogAkkaLogger.HoconTypeName}\"]\nakka.logger-startup-timeout = 5s"); + var system = ActorSystem.Create("serilog-logger-boot", config); + try + { + system.Log.Info("boot line"); // must not throw; goes to the static Serilog logger + Assert.False(system.WhenTerminated.IsCompleted); + } + finally + { + await system.Terminate(); + } + } + + private sealed class CollectingTarget : IExecutionLogTarget + { + public ConcurrentQueue Lines { get; } = new(); + public void Capture(CapturedLogLine line) => Lines.Enqueue(line); + } + + /// + /// ScadaBridge#56 + #120 end to end: an Akka actor's own line, logged while it serves a traced + /// execution, crosses the logger-actor hop and still reaches that execution's step log, with the + /// actor's class as its category. + /// + [Fact] + public void AkkaLine_ForATracedExecution_ReachesItsStepLog() + { + var serilog = new LoggerConfiguration() + .Enrich.FromLogContext() + .WriteTo.Sink(new ExecutionLogCaptureSink()) + .CreateLogger(); + var bridge = Sys.ActorOf(Props.Create(() => new SerilogAkkaLogger(serilog))); + Sys.EventStream.Subscribe(bridge, typeof(AkkaLogEvent)); + var id = Guid.NewGuid(); + var target = new CollectingTarget(); + using var registration = ExecutionLogCapture.Register(id, target); + + Sys.ActorOf(Props.Create(() => new LoggingActor())).Tell(((Guid?)id, "gamma")); + ExpectMsg("done"); + + AwaitCondition(() => !target.Lines.IsEmpty, TimeSpan.FromSeconds(5)); + var line = Assert.Single(target.Lines); + Assert.Equal("warn", line.Level); + Assert.Equal(typeof(LoggingActor).FullName, line.Category); + Assert.Equal("actor line \"gamma\"", line.Message); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundNodeLogCaptureTests.cs b/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundNodeLogCaptureTests.cs new file mode 100644 index 00000000..a579867a --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.InboundAPI.Tests/InboundNodeLogCaptureTests.cs @@ -0,0 +1,127 @@ +using Microsoft.Extensions.Logging; +using NSubstitute; +using Serilog; +using ZB.MOM.WW.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Entities.InboundApi; +using ZB.MOM.WW.ScadaBridge.Commons.Interfaces.Services; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; + +namespace ZB.MOM.WW.ScadaBridge.InboundAPI.Tests; + +/// +/// ScadaBridge#56 (central half): while a method request is traced, other central node-log lines +/// tagged with its ExecutionId become node rows of the request; the script's own +/// Log.* line and the executor's outcome line are not copied, and an untraced request copies +/// nothing. +/// +public class InboundNodeLogCaptureTests +{ + private readonly Serilog.ILogger _node = new LoggerConfiguration() + .MinimumLevel.Information() + .Enrich.FromLogContext() + .WriteTo.Sink(new ExecutionLogCaptureSink()) + .CreateLogger(); + + private readonly InboundScriptExecutor _executor; + private readonly ApiMethod _method = new("node", "x") { Id = 1, TimeoutSeconds = 10 }; + + /// Builds an executor whose own logger writes to the node pipeline, like the host's. + public InboundNodeLogCaptureTests() + => _executor = new InboundScriptExecutor(new SerilogMel(_node), Substitute.For()); + + private sealed class SerilogMel(Serilog.ILogger inner) : ILogger + { + private readonly Serilog.ILogger _inner = inner.ForContext("SourceContext", typeof(InboundScriptExecutor).FullName); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Information; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + if (!IsEnabled(logLevel)) return; + var level = logLevel switch + { + LogLevel.Information => Serilog.Events.LogEventLevel.Information, + LogLevel.Warning => Serilog.Events.LogEventLevel.Warning, + _ => Serilog.Events.LogEventLevel.Error, + }; + _inner.Write(level, exception, "{Message:l}", formatter(state, exception)); + } + } + + private async Task> RunAsync( + Func> handler, bool trace) + { + _executor.RegisterHandler("node", handler); + var sink = new List(); + var route = new RouteHelper(Substitute.For(), Substitute.For()) + .WithTraceSink(e => { lock (sink) sink.Add(e); }); + await _executor.ExecuteAsync(_method, new Dictionary(), route, TimeSpan.FromSeconds(10), + parentExecutionId: Guid.NewGuid(), trace: trace); + lock (sink) + { + return sink + .Select(e => AuditDetailsCodec.Deserialize(e.DetailsJson)) + .Where(d => d.Kind == nameof(AuditKind.ScriptLog)) + .Select(d => (d, ScriptTraceExtra.TryParse(d.Extra)!)) + .ToList(); + } + } + + /// A callee's line on the request's flow becomes a node row with its category. + /// A task that represents the asynchronous operation. + [Fact] + public async Task TracedRequest_CalleeLine_IsANodeRow() + { + var rows = await RunAsync(async _ => + { + await Task.Yield(); + _node.ForContext("SourceContext", "Acme.InboundDatabaseHelper").Warning("query retried {Count}", 2); + return null; + }, trace: true); + + var row = Assert.Single(rows); + Assert.Equal("node", row.Extra.LogSource); + Assert.Equal("warn", row.Extra.LogLevel); + Assert.Equal("Acme.InboundDatabaseHelper", row.Extra.LogCategory); + Assert.Equal("query retried 2", row.Details.RequestSummary); + } + + /// An untraced request registers nothing, so the same line is not captured. + /// A task that represents the asynchronous operation. + [Fact] + public async Task UntracedRequest_CapturesNothing() + { + var rows = await RunAsync(_ => + { + _node.Warning("query retried"); + return Task.FromResult(null); + }, trace: false); + + Assert.Empty(rows); + } + + /// + /// The script's own Log line is one script row (its node forward is suppressed), and the + /// executor's failure line is the inbound row's error, so it is not copied. + /// + /// A task that represents the asynchronous operation. + [Fact] + public async Task ScriptLine_AndExecutorFailureLine_AreNotCopied() + { + var rows = await RunAsync(ctx => + { + ctx.Log.Info("from the script"); + throw new InvalidOperationException("boom"); + }, trace: true); + + var row = Assert.Single(rows); + Assert.Equal("script", row.Extra.LogSource); + Assert.Equal("from the script", row.Details.RequestSummary); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/NodeLogCaptureTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/NodeLogCaptureTests.cs new file mode 100644 index 00000000..80875a07 --- /dev/null +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/NodeLogCaptureTests.cs @@ -0,0 +1,312 @@ +using Akka.Actor; +using Akka.TestKit.Xunit2; +using Microsoft.CodeAnalysis.CSharp.Scripting; +using Microsoft.CodeAnalysis.Scripting; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using ZB.MOM.WW.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.Instance; +using ZB.MOM.WW.ScadaBridge.Commons.Messages.ScriptExecution; +using ZB.MOM.WW.ScadaBridge.Commons.Observability; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Audit; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Debugging; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Enums; +using ZB.MOM.WW.ScadaBridge.Commons.Types.Scripts; +using ZB.MOM.WW.ScadaBridge.SiteRuntime.Scripts; + +namespace ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests.Scripts; + +/// +/// ScadaBridge#56: while a run is traced, node-log lines that OTHER actors write for it (tagged with +/// its ExecutionId) are copied into its ScriptLog rows as source node — under the +/// run's line cap, through the same collector (and so the same redaction) as every other row — and +/// an untraced run copies nothing. +/// +public class NodeLogCaptureTests : TestKit, IDisposable +{ + private readonly ScriptExecutionScheduler _scheduler = new(4); + private readonly SharedScriptLibrary _sharedLibrary = new( + new ScriptCompilationService(NullLogger.Instance), + NullLogger.Instance); + + /// The node's Serilog pipeline as the host builds it: LogContext enrichment plus the capture sink. + private readonly Serilog.ILogger _node = new Serilog.LoggerConfiguration() + .MinimumLevel.Information() + .Enrich.FromLogContext() + .WriteTo.Sink(new ExecutionLogCaptureSink()) + .CreateLogger(); + + /// + void IDisposable.Dispose() + { + Shutdown(); + _scheduler.Dispose(); + } + + /// A Microsoft logger over a Serilog logger (the host's UseSerilog shape), with a category. + private sealed class SerilogMel(Serilog.ILogger inner, string category) : ILogger + { + private readonly Serilog.ILogger _inner = inner.ForContext("SourceContext", category); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Information; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + if (!IsEnabled(logLevel)) return; + var level = logLevel switch + { + LogLevel.Information => Serilog.Events.LogEventLevel.Information, + LogLevel.Warning => Serilog.Events.LogEventLevel.Warning, + _ => Serilog.Events.LogEventLevel.Error, + }; + _inner.Write(level, exception, "{Message:l}", formatter(state, exception)); + } + } + + /// + /// Stands in for the Instance Actor: re-pushes the message's execution id (as the real one does in + /// AroundReceive), logs a line on ITS thread, and acknowledges the write. + /// + private sealed class LoggingInstanceActor : ReceiveActor + { + public LoggingInstanceActor(Serilog.ILogger node) + { + var log = node.ForContext("SourceContext", "ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors.InstanceActor"); + Receive(cmd => + { + using (ExecutionLogContext.PushFor(cmd)) + { + log.Warning("instance actor applied {Attribute} token=hunter2", cmd.AttributeName); + } + + Sender.Tell(new SetStaticAttributeResponse( + cmd.CorrelationId, cmd.InstanceUniqueName, cmd.AttributeName, true, null, DateTimeOffset.UtcNow)); + }); + } + } + + private static Script Compile(string code) + { + var options = ScriptOptions.Default + .WithReferences(typeof(object).Assembly, typeof(Enumerable).Assembly, typeof(ScriptGlobals).Assembly) + .WithImports("System", "System.Collections.Generic", "System.Linq", "System.Threading.Tasks"); + var script = CSharpScript.Create(code, options, typeof(ScriptGlobals)); + script.Compile(); + return script; + } + + private ScriptCallResult Run(string body, bool trace, int maxLogLines = 200) + { + var caller = CreateTestProbe(); + var instance = Sys.ActorOf(Props.Create(() => new LoggingInstanceActor(_node))); + ScriptRunLauncher.LaunchScript( + scriptName: "Runner", instanceName: "Inst1", compiledScript: Compile(body), + parameters: null, callDepth: 0, instanceActor: instance, + sharedScriptLibrary: _sharedLibrary, + options: new SiteRuntimeOptions + { + MaxScriptCallDepth = 10, ScriptExecutionTimeoutSeconds = 30, StuckScriptGraceMs = 30000, + MaxLogLinesPerRun = maxLogLines, + }, + replyTo: caller.Ref, correlationId: "corr-1", completionTarget: CreateTestProbe().Ref, + siteCommunicationActor: null, + logger: new SerilogMel(_node, "ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors.ScriptActor"), + scope: ScriptScope.Root, runId: 1, healthCollector: null, serviceProvider: null, + parentExecutionId: null, executionTimeoutSeconds: null, scheduler: _scheduler, + trace: trace, triggerExtra: null); + return caller.ExpectMsg(TimeSpan.FromSeconds(20)); + } + + private static List<(AuditEvent Event, ScriptTraceExtra Extra)> LogRows(ScriptCallResult result) + => result.TraceEvents! + .Where(e => e.AsRow().Kind == AuditKind.ScriptLog) + .Select(e => (e, ScriptTraceExtra.TryParse(e.AsRow().Extra)!)) + .ToList(); + + /// + /// Cross-actor: the Instance Actor's line, written on its own thread while serving the traced + /// run's write, comes back inline as a node row of that run, with its category and level. + /// + [Fact] + public void TracedRun_OtherActorsLine_IsCapturedAsANodeRow() + { + var result = Run("await Instance.SetAttribute(\"Setpoint\", \"42\"); return null;", trace: true); + + Assert.True(result.Success, result.ErrorMessage); + var node = Assert.Single(LogRows(result), r => r.Extra.LogSource == "node"); + Assert.Equal("warn", node.Extra.LogLevel); + Assert.Equal("ZB.MOM.WW.ScadaBridge.SiteRuntime.Actors.InstanceActor", node.Extra.LogCategory); + Assert.Contains("instance actor applied \"Setpoint\"", node.Event.AsRow().RequestSummary); + Assert.Equal(result.ExecutionId, node.Event.AsRow().ExecutionId); + // The registration ends with the run: a later line for the same id is not captured. + Assert.False(ExecutionLogCapture.TryGetTarget(result.ExecutionId!.Value, out _)); + } + + /// + /// An inline shared script's write is stamped with the SHARED script's own execution id; its + /// node line still lands in the caller's rows (where the shared script's Log.* lines go). + /// + [Fact] + public void SharedScriptsWrite_NodeLine_LandsInTheCallersRows() + { + Assert.True(_sharedLibrary.CompileAndRegister( + "WriteHelper", "await Instance.SetAttribute(\"FromShared\", \"1\"); return null;")); + + var result = Run("await Instance.Scripts.CallShared(\"WriteHelper\"); return null;", trace: true); + + Assert.True(result.Success, result.ErrorMessage); + var node = Assert.Single(LogRows(result), r => r.Extra.LogSource == "node"); + Assert.Contains("FromShared", node.Event.AsRow().RequestSummary); + Assert.Equal(result.ExecutionId, node.Event.AsRow().ExecutionId); + } + + /// An untraced run never registers, so the same line is not captured (and the reply has no rows). + [Fact] + public void UntracedRun_CapturesNothing() + { + var result = Run("await Instance.SetAttribute(\"Setpoint\", \"42\"); return null;", trace: false); + + Assert.True(result.Success, result.ErrorMessage); + Assert.True(result.TraceEvents is null || result.TraceEvents.Count == 0); + } + + /// + /// No double capture: the script's own Log.Info goes to the node logger (tagged with the run's + /// id) and is a script row exactly once — never a second node row. The launcher's + /// own failure line is the ScriptRun row, so it is not copied either. + /// + [Fact] + public void ScriptLogLine_AndLauncherFailureLine_AreNotCopiedAsNodeRows() + { + var result = Run("Log.Info(\"hello\"); throw new InvalidOperationException(\"boom\");", trace: true); + + Assert.False(result.Success); + var rows = LogRows(result); + var script = Assert.Single(rows); + Assert.Equal("script", script.Extra.LogSource); + Assert.Equal("hello", script.Event.AsRow().RequestSummary); + } + + /// + /// Node rows share the run's line cap with the script's own lines: past it they are dropped and + /// the closing runtime row names the count. + /// + [Fact] + public void NodeRows_ShareTheRunsLineCap() + { + var result = Run( + "Log.Info(\"one\"); for (var i = 0; i < 3; i++) await Instance.SetAttribute(\"A\" + i, \"1\"); return null;", + trace: true, maxLogLines: 2); + + Assert.True(result.Success, result.ErrorMessage); + var rows = LogRows(result); + Assert.Equal(3, rows.Count); // "one" + 1 node row + the closing row + Assert.Single(rows, r => r.Extra.LogSource == "node"); + var closing = Assert.Single(rows, r => r.Extra.LogSource == "runtime"); + Assert.Contains("2 further log line(s)", closing.Event.AsRow().RequestSummary); + } + + /// + /// Node rows ride the same inline collector as every other row, so its redactor applies: what Live + /// shows is what Replay stores. + /// + /// A task that represents the asynchronous operation. + [Fact] + public async Task NodeRows_PassTheCollectorsRedactor() + { + var collector = new FlowTraceCollector(redactor: new TokenRedactor()); + var exec = Guid.NewGuid(); + var ctx = new ScriptRuntimeContext( + Sys.ActorOf(Props.Create(() => new LoggingInstanceActor(_node))), _sharedLibrary, + currentCallDepth: 0, maxCallDepth: 10, askTimeout: TimeSpan.FromSeconds(5), + instanceName: "Inst1", logger: NullLogger.Instance, siteId: "site-a", + sourceScript: "ScriptActor:Runner", executionId: exec, isTraced: true, traceCollector: collector); + + using (ctx.Log.CaptureNodeLines(exec)) + { + await ctx.SetAttribute("Setpoint", "42"); + } + + var node = Assert.Single(collector.Complete(), e => e.AsRow().Kind == AuditKind.ScriptLog); + Assert.DoesNotContain("hunter2", node.DetailsJson); + Assert.Contains("token=***", node.AsRow().RequestSummary); + } + + /// Scrubs hunter2 from the details, standing in for the host's body-regex redaction. + private sealed class TokenRedactor : IAuditRedactor + { + public AuditEvent Apply(AuditEvent rawEvent) + => rawEvent with { DetailsJson = rawEvent.DetailsJson?.Replace("hunter2", "***", StringComparison.Ordinal) }; + } + + private (ScriptLogger Logger, List<(string Level, string Source, string Message, string? Category)> Rows) Traced(Guid id) + { + var rows = new List<(string, string, string, string?)>(); + var logger = new ScriptLogger( + new SerilogMel(_node, "ScriptActor"), + (level, source, message, _, _, category, _) => { lock (rows) rows.Add((level, source, message, category)); }, + maxLines: 200, "Inst1", "Runner", id); + return (logger, rows); + } + + /// An untraced logger never touches the registry. + [Fact] + public void UntracedLogger_CaptureNodeLines_DoesNotRegister() + { + var id = Guid.NewGuid(); + var untraced = new ScriptLogger(NullLogger.Instance, emit: null, maxLines: 200, "Inst1", "Runner", id); + + using (untraced.CaptureNodeLines(id)) + { + Assert.False(ExecutionLogCapture.TryGetTarget(id, out _)); + } + } + + /// FlushDropped (every run-end path) closes the copy, and a capture opened after it is refused. + [Fact] + public void FlushDropped_ClosesTheCopy() + { + var id = Guid.NewGuid(); + var (logger, rows) = Traced(id); + var capture = logger.CaptureNodeLines(id); + Assert.True(ExecutionLogCapture.TryGetTarget(id, out _)); + + logger.FlushDropped(); + + Assert.False(ExecutionLogCapture.TryGetTarget(id, out _)); + using (logger.CaptureNodeLines(id)) + using (ExecutionLogContext.Push(id)) + { + _node.Warning("after the run"); + } + + Assert.Empty(rows); + capture.Dispose(); + } + + /// + /// The runtime decorator's forward is suppressed: a runtime warning logged while traced is one + /// runtime row, never a second node row — while a genuine other-actor line still is one. + /// + [Fact] + public void RuntimeLine_IsNotCopiedAgain_ButAnotherLoggersLineIs() + { + var id = Guid.NewGuid(); + var (logger, rows) = Traced(id); + var runtime = new TraceCapturingLogger(new SerilogMel(_node, "ScriptActor"), logger); + + using (logger.CaptureNodeLines(id)) + using (ExecutionLogContext.Push(id)) + { + runtime.LogWarning("runtime warning"); + _node.ForContext("SourceContext", "Acme.Other").Warning("other actor"); + } + + Assert.Equal( + [("warn", "runtime", "runtime warning", (string?)null), ("warn", "node", "other actor", "Acme.Other")], + rows); + } +} diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs index be2c6fe1..f204d089 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/ScriptLoggerTests.cs @@ -54,7 +54,7 @@ public class ScriptLoggerTests var rows = new List(); var logger = new ScriptLogger( node, - (level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)), + (level, source, message, exception, stepEventId, _, _) => rows.Add(new Row(level, source, message, exception, stepEventId)), maxLines, instance: "CvdReactor01", script: "OnHeartbeat", @@ -252,7 +252,7 @@ public class ScriptLoggerTests var node = new RecordingLogger(); var logger = new ScriptLogger( node, - (_, _, _, _, _) => throw new InvalidOperationException("collector is broken"), + (_, _, _, _, _, _, _) => throw new InvalidOperationException("collector is broken"), maxLines: 200, "CvdReactor01", "OnHeartbeat", @@ -271,7 +271,7 @@ public class ScriptLoggerTests var rows = new List(); var logger = new ScriptLogger( new ThrowingLogger(), - (level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)), + (level, source, message, exception, stepEventId, _, _) => rows.Add(new Row(level, source, message, exception, stepEventId)), maxLines: 200, "CvdReactor01", "OnHeartbeat", diff --git a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs index 4bc2ca02..5ce4e9bb 100644 --- a/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs +++ b/tests/ZB.MOM.WW.ScadaBridge.SiteRuntime.Tests/Scripts/TraceCapturingLoggerTests.cs @@ -55,7 +55,7 @@ public class TraceCapturingLoggerTests var rows = new List(); var sink = new ScriptLogger( new RecordingLogger(), - (level, source, message, exception, stepEventId) => rows.Add(new Row(level, source, message, exception, stepEventId)), + (level, source, message, exception, stepEventId, _, _) => rows.Add(new Row(level, source, message, exception, stepEventId)), maxLines: 200, instance: "CvdReactor01", script: "OnHeartbeat",